Investigation of PowerTAC Issue #565

565-investigation.txt

19 June 2012. Investigating issue #565:

Symptom: TariffTransactions are being generated with null spec
values. First incident:

255374:org.powertac.common.TariffTransaction::21642::new::598::2009-02-09T09:00:00.000Z::CONSUME::null::485::5::-1485.63::783090.442937034
255374:org.powertac.common.TariffTransaction::21643::new::598::2009-02-09T09:00:00.000Z::PERIODIC::null::485::5::0.0::0.20833333333333334

Customer 485 is EastsideOffices, total population 25.

Hypothesis: Tariff has been revoked and deleted, but subscription was
not updated correctly.

Record of signups and withdrawals for Customer 485:

11673:org.powertac.common.TariffTransaction::493::new::1::2009-02-08T00:00:00.000Z::SIGNUP::391::485::25::0.0::-0.0
100566:org.powertac.common.TariffTransaction::2431::new::598::2009-02-08T02:00:00.000Z::SIGNUP::200000391::485::25::0.0::-0.0
100566:org.powertac.common.TariffTransaction::2432::new::1::2009-02-08T02:00:00.000Z::WITHDRAW::391::485::25::0.0::-0.0
130433:org.powertac.common.TariffTransaction::5729::new::598::2009-02-08T08:00:00.000Z::WITHDRAW::200000391::485::7::0.0::-0.0
130433:org.powertac.common.TariffTransaction::5730::new::1::2009-02-08T08:00:00.000Z::SIGNUP::391::485::7::0.0::-0.0
190385:org.powertac.common.TariffTransaction::13258::new::1::2009-02-08T20:00:00.000Z::SIGNUP::391::485::2::0.0::-0.0
190385:org.powertac.common.TariffTransaction::13260::new::598::2009-02-08T20:00:00.000Z::SIGNUP::200000427::485::6::0.0::-0.0
190386:org.powertac.common.TariffTransaction::13261::new::598::2009-02-08T20:00:00.000Z::WITHDRAW::200000391::485::8::0.0::-0.0
250410:org.powertac.common.TariffTransaction::21092::new::598::2009-02-09T08:00:00.000Z::SIGNUP::200000427::485::1::0.0::-0.0
250410:org.powertac.common.TariffTransaction::21093::new::598::2009-02-09T08:00:00.000Z::WITHDRAW::200000391::485::3::0.0::-0.0
250410:org.powertac.common.TariffTransaction::21095::new::598::2009-02-09T08:00:00.000Z::SIGNUP::null::485::5::0.0::-0.0
250410:org.powertac.common.TariffTransaction::21096::new::1::2009-02-09T08:00:00.000Z::WITHDRAW::391::485::3::0.0::-0.0

The null value happens when the arg value is null.
So here we have EastsideOffices subscribing to a null tariff.

This is happening during the tariffMarket activation in timeslot 392:

250398 INFO  server.CompetitionControlService: activate phase 4
250398 INFO  tariffmarket.TariffMarketService: Activate
250419 INFO  server.CompetitionControlService: activate phase 5

The pattern matches the activity in TariffMarketService.processPendingSubscriptions().

Shortly before this, at the end of timeslot 390, Mertacor revoked two tariffs:

241563 INFO  server.ServerMessageReceiver: onMessage(String) - received message:
<tariff-rev id="200000497" tariffId="200000467">
  <broker>Mertacor</broker>
</tariff-rev>
241738 INFO  server.ServerMessageReceiver: onMessage(String) - received message:
<tariff-rev id="200000498" tariffId="200000471">
  <broker>Mertacor</broker>
</tariff-rev>

Then in timeslot 391, household-customer triggers revocation
processing:

245352 INFO  householdcustomer.HouseholdCustomerService: Activate
245352 INFO  tariffmarket.TariffMarketService: Revoke tariff 200000467
245353 INFO  tariffmarket.TariffMarketService: Revoked tariff 200000467 has 2 active subscriptions
245354 INFO  tariffmarket.TariffMarketService: Revoke tariff 200000471

Further on, we see anomalous behavior with regard to this tariff. The
factored-customer model recognizes it as KILLED, and switches its
subscription to the default tariff, but then uses power against the
revoked tariff anyway:

245363 INFO  factoredcustomer.DefaultFactoredCustomer: Customer BrooksideHomes activated for timeslot 391
245363 INFO  common.TariffSubscription: Tariff 200000467 superseded by 391 for 955customers
245363 INFO  factoredcustomer.DefaultCapacityOriginator: BrooksideHomes: Adjusted capacity for tariff 391 = 3694.84
245363 INFO  common.TariffSubscription: usePower 3694.84, actual 3694.84, customer=BrooksideHomes
245363 INFO  factoredcustomer.DefaultCapacityOriginator: BrooksideHomes: Adjusted capacity for tariff 200000391 = 5285.23
245363 INFO  common.TariffSubscription: usePower 5285.23, actual 5285.23, customer=BrooksideHomes
245363 INFO  factoredcustomer.DefaultCapacityOriginator: BrooksideHomes: Adjusted capacity for tariff 200000407 = 3684.01
245363 INFO  common.TariffSubscription: usePower 3684.01, actual 3684.01, customer=BrooksideHomes
245363 INFO  factoredcustomer.DefaultCapacityOriginator: BrooksideHomes: Adjusted capacity for tariff 200000427 = 3564.84
245363 INFO  common.TariffSubscription: usePower 3564.84, actual 3564.84, customer=BrooksideHomes
245364 INFO  factoredcustomer.DefaultCapacityOriginator: BrooksideHomes: Adjusted capacity for tariff 200000447 = 2837.79
245364 INFO  common.TariffSubscription: usePower 2837.79, actual 2837.79, customer=BrooksideHomes
245364 INFO  factoredcustomer.DefaultCapacityOriginator: BrooksideHomes: Adjusted capacity for tariff 200000467 = 574.78
245364 INFO  common.TariffSubscription: usePower 574.78, actual 574.78, customer=BrooksideHomes
245364 INFO  factoredcustomer.DefaultUtilityOptimizer: BrooksideHomes: Total CONSUMPTION capacity for timeslot 391 = 19641.489999999998
245364 INFO  factoredcustomer.LearningFactoredCustomer: Customer CentervilleHomes activated for timeslot 391
245364 INFO  common.TariffSubscription: Tariff 200000467 superseded by 391 for 448customers
245364 INFO  factoredcustomer.AdaptiveCapacityOriginator: CentervilleHomes: Adjusted capacity for tariff 391 = 2080.6
245364 INFO  common.TariffSubscription: usePower 2080.6, actual 2080.6, customer=CentervilleHomes
245364 INFO  factoredcustomer.AdaptiveCapacityOriginator: CentervilleHomes: Adjusted capacity for tariff 200000391 = 2977.28
245364 INFO  common.TariffSubscription: usePower 2977.28, actual 2977.28, customer=CentervilleHomes
245364 INFO  factoredcustomer.AdaptiveCapacityOriginator: CentervilleHomes: Adjusted capacity for tariff 200000407 = 2072.63
245364 INFO  common.TariffSubscription: usePower 2072.63, actual 2072.63, customer=CentervilleHomes
245365 INFO  factoredcustomer.AdaptiveCapacityOriginator: CentervilleHomes: Adjusted capacity for tariff 200000427 = 1992.87
245365 INFO  common.TariffSubscription: usePower 1992.87, actual 1992.87, customer=CentervilleHomes
245365 INFO  factoredcustomer.AdaptiveCapacityOriginator: CentervilleHomes: Adjusted capacity for tariff 200000447 = 1515.84
245365 INFO  common.TariffSubscription: usePower 1515.84, actual 1515.84, customer=CentervilleHomes
245365 INFO  factoredcustomer.AdaptiveCapacityOriginator: CentervilleHomes: Adjusted capacity for tariff 200000467 = 223.31
245365 INFO  common.TariffSubscription: usePower 223.31, actual 223.31, customer=CentervilleHomes
245365 INFO  factoredcustomer.LearningUtilityOptimizer: CentervilleHomes: Total CONSUMPTION capacity for timeslot 391 = 10862.53

At this point, EastsideOffices does not seem to have a subscription to
tariff 200000467. But later in this timeslot, EastsideOffices
subscribes 5 of its members to this revoked tariff:

245613 INFO  factoredcustomer.LearningFactoredCustomer: Customer EastsideOffices received 3 new tariffs at timeslot 391
245613 INFO  factoredcustomer.LearningUtilityOptimizer: EastsideOffices: Subscribing 1 CONSUMPTION customers to tariff 200000427
245613 INFO  factoredcustomer.LearningUtilityOptimizer: EastsideOffices: Unsubscribing 3 CONSUMPTION customers from tariff 200000391
245613 INFO  factoredcustomer.LearningUtilityOptimizer: EastsideOffices: Not allocating any CONSUMPTION customers to tariff 200000487
245613 INFO  factoredcustomer.LearningUtilityOptimizer: EastsideOffices: Subscribing 5 CONSUMPTION customers to tariff 200000467
245613 INFO  factoredcustomer.LearningUtilityOptimizer: EastsideOffices: Unsubscribing 3 CONSUMPTION customers from tariff 391

Later, during TariffMarketService processing, revoked tariffs are
deleted, and this leads to the null value.