Code Coverage |
||||||||||
Lines |
Functions and Methods |
Classes and Traits |
||||||||
| Total | |
72.39% |
97 / 134 |
|
50.00% |
5 / 10 |
CRAP | |
0.00% |
0 / 1 |
| LoggingHelper | |
72.39% |
97 / 134 |
|
50.00% |
5 / 10 |
26.60 | |
0.00% |
0 / 1 |
| __construct | |
100.00% |
10 / 10 |
|
100.00% |
1 / 1 |
1 | |||
| findLimit | |
100.00% |
8 / 8 |
|
100.00% |
1 / 1 |
6 | |||
| logConstraintCheck | |
95.24% |
40 / 42 |
|
0.00% |
0 / 1 |
4 | |||
| logConstraintCheckOnEntity | |
100.00% |
24 / 24 |
|
100.00% |
1 / 1 |
2 | |||
| logCheckConstraintsCacheHit | |
0.00% |
0 / 3 |
|
0.00% |
0 / 1 |
2 | |||
| logCheckConstraintsCacheMisses | |
0.00% |
0 / 4 |
|
0.00% |
0 / 1 |
2 | |||
| logEmptyDependencyMetadata | |
0.00% |
0 / 10 |
|
0.00% |
0 / 1 |
2 | |||
| logHugeDependencyMetadata | |
0.00% |
0 / 18 |
|
0.00% |
0 / 1 |
2 | |||
| logSparqlHelperTooManyRequestsRetryAfterPresent | |
100.00% |
8 / 8 |
|
100.00% |
1 / 1 |
1 | |||
| logSparqlHelperTooManyRequestsRetryAfterInvalid | |
100.00% |
7 / 7 |
|
100.00% |
1 / 1 |
1 | |||
| 1 | <?php |
| 2 | |
| 3 | namespace WikibaseQuality\ConstraintReport\ConstraintCheck\Helper; |
| 4 | |
| 5 | use MediaWiki\Config\Config; |
| 6 | use MWHttpRequest; |
| 7 | use Psr\Log\LoggerInterface; |
| 8 | use Wikibase\DataModel\Entity\EntityId; |
| 9 | use WikibaseQuality\ConstraintReport\Constraint; |
| 10 | use WikibaseQuality\ConstraintReport\ConstraintCheck\Context\Context; |
| 11 | use WikibaseQuality\ConstraintReport\ConstraintCheck\Result\CheckResult; |
| 12 | use Wikimedia\Stats\IBufferingStatsdDataFactory; |
| 13 | use Wikimedia\Timestamp\ConvertibleTimestamp; |
| 14 | |
| 15 | /** |
| 16 | * Helper class for tracking and logging messages. |
| 17 | * |
| 18 | * @author Lucas Werkmeister |
| 19 | * @license GPL-2.0-or-later |
| 20 | */ |
| 21 | class LoggingHelper { |
| 22 | |
| 23 | /** |
| 24 | * @var IBufferingStatsdDataFactory |
| 25 | */ |
| 26 | private $dataFactory; |
| 27 | |
| 28 | /** |
| 29 | * @var LoggerInterface |
| 30 | */ |
| 31 | private $logger; |
| 32 | |
| 33 | /** |
| 34 | * @var float[] |
| 35 | */ |
| 36 | private $constraintCheckDurationLimits; |
| 37 | |
| 38 | /** |
| 39 | * @var float[] |
| 40 | */ |
| 41 | private $constraintCheckOnEntityDurationLimits; |
| 42 | |
| 43 | /** |
| 44 | * @param IBufferingStatsdDataFactory $dataFactory, |
| 45 | * @param LoggerInterface $logger |
| 46 | * @param Config $config |
| 47 | */ |
| 48 | public function __construct( |
| 49 | IBufferingStatsdDataFactory $dataFactory, |
| 50 | LoggerInterface $logger, |
| 51 | Config $config |
| 52 | ) { |
| 53 | $this->dataFactory = $dataFactory; |
| 54 | $this->logger = $logger; |
| 55 | $this->constraintCheckDurationLimits = [ |
| 56 | 'info' => $config->get( 'WBQualityConstraintsCheckDurationInfoSeconds' ), |
| 57 | 'warning' => $config->get( 'WBQualityConstraintsCheckDurationWarningSeconds' ), |
| 58 | ]; |
| 59 | $this->constraintCheckOnEntityDurationLimits = [ |
| 60 | 'info' => $config->get( 'WBQualityConstraintsCheckOnEntityDurationInfoSeconds' ), |
| 61 | 'warning' => $config->get( 'WBQualityConstraintsCheckOnEntityDurationWarningSeconds' ), |
| 62 | ]; |
| 63 | } |
| 64 | |
| 65 | /** |
| 66 | * Find the longest limit in $limits which the $durationSeconds exceeds, |
| 67 | * and return it along with the associated log level. |
| 68 | * |
| 69 | * @param float $durationSeconds |
| 70 | * @return array [ $limitSeconds, $logLevel ] |
| 71 | */ |
| 72 | private function findLimit( $limits, $durationSeconds ) { |
| 73 | $limitSeconds = null; |
| 74 | $logLevel = null; |
| 75 | |
| 76 | foreach ( $limits as $level => $limit ) { |
| 77 | if ( |
| 78 | // duration exceeds this limit |
| 79 | $limit !== null && $durationSeconds > $limit && |
| 80 | // this limit is longer than previous longest limit |
| 81 | ( $limitSeconds === null || $limit > $limitSeconds ) |
| 82 | ) { |
| 83 | $limitSeconds = $limit; |
| 84 | $logLevel = $level; |
| 85 | } |
| 86 | } |
| 87 | |
| 88 | return [ $limitSeconds, $logLevel ]; |
| 89 | } |
| 90 | |
| 91 | /** |
| 92 | * Log a single constraint check. |
| 93 | * The constraint check is tracked on the statsd data factory, |
| 94 | * and also logged with the logger interface if it took longer than a certain time. |
| 95 | * Multiple limits corresponding to different log levels can be specified in the configuration; |
| 96 | * checks that exceed a higher limit are logged at a more severe level. |
| 97 | * |
| 98 | * @param Context $context |
| 99 | * @param Constraint $constraint |
| 100 | * @param CheckResult $result |
| 101 | * @param string $constraintCheckerClass |
| 102 | * @param float $durationSeconds |
| 103 | * @param string $method Use __METHOD__. |
| 104 | */ |
| 105 | public function logConstraintCheck( |
| 106 | Context $context, |
| 107 | Constraint $constraint, |
| 108 | CheckResult $result, |
| 109 | $constraintCheckerClass, |
| 110 | $durationSeconds, |
| 111 | $method |
| 112 | ) { |
| 113 | $constraintCheckerClassShortName = substr( strrchr( $constraintCheckerClass, '\\' ), 1 ); |
| 114 | $constraintTypeItemId = $constraint->getConstraintTypeItemId(); |
| 115 | |
| 116 | $this->dataFactory->timing( |
| 117 | 'wikibase.quality.constraints.check.timing.' . |
| 118 | $constraintTypeItemId . '-' . |
| 119 | $constraintCheckerClassShortName, |
| 120 | $durationSeconds * 1000 |
| 121 | ); |
| 122 | |
| 123 | // find the longest limit (and associated log level) that the duration exceeds |
| 124 | [ $limitSeconds, $logLevel ] = $this->findLimit( |
| 125 | $this->constraintCheckDurationLimits, |
| 126 | $durationSeconds |
| 127 | ); |
| 128 | if ( $limitSeconds === null ) { |
| 129 | return; |
| 130 | } |
| 131 | if ( $context->getType() !== Context::TYPE_STATEMENT ) { |
| 132 | // TODO log less details but still log something |
| 133 | return; |
| 134 | } |
| 135 | |
| 136 | $resultMessage = $result->getMessage(); |
| 137 | if ( $resultMessage !== null ) { |
| 138 | $resultMessageKey = $resultMessage->getMessageKey(); |
| 139 | } else { |
| 140 | $resultMessageKey = null; |
| 141 | } |
| 142 | |
| 143 | $this->logger->log( |
| 144 | $logLevel, |
| 145 | 'Constraint check with {constraintCheckerClassShortName} ' . |
| 146 | 'took longer than {limitSeconds} second(s) ' . |
| 147 | '(duration: {durationSeconds} seconds).', |
| 148 | [ |
| 149 | 'method' => $method, |
| 150 | 'loggingMethod' => __METHOD__, |
| 151 | 'durationSeconds' => $durationSeconds, |
| 152 | 'limitSeconds' => $limitSeconds, |
| 153 | 'constraintId' => $constraint->getConstraintId(), |
| 154 | 'constraintPropertyId' => $constraint->getPropertyId()->getSerialization(), |
| 155 | 'constraintTypeItemId' => $constraintTypeItemId, |
| 156 | 'constraintParameters' => json_encode( $constraint->getConstraintParameters() ), |
| 157 | 'constraintCheckerClass' => $constraintCheckerClass, |
| 158 | 'constraintCheckerClassShortName' => $constraintCheckerClassShortName, |
| 159 | 'entityId' => $context->getEntity()->getId()->getSerialization(), |
| 160 | 'statementGuid' => $context->getSnakStatement()->getGuid(), |
| 161 | 'resultStatus' => $result->getStatus(), |
| 162 | 'resultMessage' => $resultMessageKey, |
| 163 | ] |
| 164 | ); |
| 165 | } |
| 166 | |
| 167 | /** |
| 168 | * Log a full constraint check on an entity. |
| 169 | * The constraint check is tracked on the statsd data factory, |
| 170 | * and also logged with the logger interface if it took longer than a certain time. |
| 171 | * Multiple limits corresponding to different log levels can be specified in the configuration; |
| 172 | * checks that exceed a higher limit are logged at a more severe level. |
| 173 | * |
| 174 | * |
| 175 | * @param EntityId $entityId |
| 176 | * @param CheckResult[] $checkResults |
| 177 | * @param float $durationSeconds |
| 178 | */ |
| 179 | public function logConstraintCheckOnEntity( |
| 180 | EntityId $entityId, |
| 181 | array $checkResults, |
| 182 | $durationSeconds, |
| 183 | $method |
| 184 | ) { |
| 185 | $this->dataFactory->timing( |
| 186 | 'wikibase.quality.constraints.check.entity.timing', |
| 187 | $durationSeconds * 1000 |
| 188 | ); |
| 189 | |
| 190 | // find the longest limit (and associated log level) that the duration exceeds |
| 191 | [ $limitSeconds, $logLevel ] = $this->findLimit( |
| 192 | $this->constraintCheckOnEntityDurationLimits, |
| 193 | $durationSeconds |
| 194 | ); |
| 195 | if ( $limitSeconds === null ) { |
| 196 | return; |
| 197 | } |
| 198 | |
| 199 | $this->logger->log( |
| 200 | $logLevel, |
| 201 | 'Full constraint check on {entityId} ' . |
| 202 | 'took longer than {limitSeconds} second(s) ' . |
| 203 | '(duration: {durationSeconds} seconds).', |
| 204 | [ |
| 205 | 'method' => $method, |
| 206 | 'loggingMethod' => __METHOD__, |
| 207 | 'durationSeconds' => $durationSeconds, |
| 208 | 'limitSeconds' => $limitSeconds, |
| 209 | 'entityId' => $entityId->getSerialization(), |
| 210 | // $checkResults currently not logged |
| 211 | ] |
| 212 | ); |
| 213 | } |
| 214 | |
| 215 | /** |
| 216 | * Log a cache hit for a complete constraint check result for the given entity ID. |
| 217 | * |
| 218 | * @param EntityId $entityId |
| 219 | */ |
| 220 | public function logCheckConstraintsCacheHit( EntityId $entityId ) { |
| 221 | $this->dataFactory->increment( |
| 222 | 'wikibase.quality.constraints.cache.entity.hit' |
| 223 | ); |
| 224 | } |
| 225 | |
| 226 | /** |
| 227 | * Log cache misses for a complete constraint check result for the given entity IDs. |
| 228 | * |
| 229 | * @param EntityId[] $entityIds |
| 230 | */ |
| 231 | public function logCheckConstraintsCacheMisses( array $entityIds ) { |
| 232 | $this->dataFactory->updateCount( |
| 233 | 'wikibase.quality.constraints.cache.entity.miss', |
| 234 | count( $entityIds ) |
| 235 | ); |
| 236 | } |
| 237 | |
| 238 | /** |
| 239 | * Log that the dependency metadata for a check result had an empty set of entity IDs. |
| 240 | * This should never happen – at least the entity being checked should always be contained. |
| 241 | */ |
| 242 | public function logEmptyDependencyMetadata() { |
| 243 | $this->logger->log( |
| 244 | 'warning', |
| 245 | 'Dependency metadata for constraint check result had empty set of entity IDs.', |
| 246 | [ |
| 247 | 'loggingMethod' => __METHOD__, |
| 248 | // callers of this method don’t have much information to pass to us, |
| 249 | // so for now we don’t log any other structured data |
| 250 | // and hope that the request URL provides enough information |
| 251 | ] |
| 252 | ); |
| 253 | } |
| 254 | |
| 255 | /** |
| 256 | * Log that the dependency metadata for a check result has a very large set of entity IDs. |
| 257 | * |
| 258 | * @param EntityId[] $entityIds |
| 259 | * @param int $maxRevisionIds |
| 260 | */ |
| 261 | public function logHugeDependencyMetadata( array $entityIds, $maxRevisionIds ) { |
| 262 | $this->logger->log( |
| 263 | 'warning', |
| 264 | 'Dependency metadata for constraint check result has huge set of entity IDs ' . |
| 265 | '(count ' . count( $entityIds ) . ', limit ' . $maxRevisionIds . '); ' . |
| 266 | 'caching disabled for this check result.', |
| 267 | [ |
| 268 | 'loggingMethod' => __METHOD__, |
| 269 | 'entityIds' => json_encode( |
| 270 | array_map( |
| 271 | static function ( EntityId $entityId ) { |
| 272 | return $entityId->getSerialization(); |
| 273 | }, |
| 274 | $entityIds |
| 275 | ) |
| 276 | ), |
| 277 | 'maxRevisionIds' => $maxRevisionIds, |
| 278 | ] |
| 279 | ); |
| 280 | } |
| 281 | |
| 282 | public function logSparqlHelperTooManyRequestsRetryAfterPresent( |
| 283 | ConvertibleTimestamp $retryAfterTime, |
| 284 | MWHttpRequest $request |
| 285 | ) { |
| 286 | $this->logger->notice( |
| 287 | 'Sparql API replied with status 429 and a retry-after header. Requesting to retry after {retryAfterTime}', |
| 288 | [ |
| 289 | 'retryAfterTime' => $retryAfterTime, |
| 290 | 'responseHeaders' => json_encode( $request->getResponseHeaders() ), |
| 291 | 'responseContent' => $request->getContent(), |
| 292 | ] |
| 293 | ); |
| 294 | } |
| 295 | |
| 296 | public function logSparqlHelperTooManyRequestsRetryAfterInvalid( MWHttpRequest $request ) { |
| 297 | $this->logger->warning( |
| 298 | 'Sparql API replied with status 429 and no valid retry-after header.', |
| 299 | [ |
| 300 | 'responseHeaders' => json_encode( $request->getResponseHeaders() ), |
| 301 | 'responseContent' => $request->getContent(), |
| 302 | ] |
| 303 | ); |
| 304 | } |
| 305 | |
| 306 | } |