|
1
|
|
|
<?php |
|
2
|
|
|
|
|
3
|
|
|
namespace WikibaseQuality\ConstraintReport\ConstraintCheck\Helper; |
|
4
|
|
|
|
|
5
|
|
|
use Config; |
|
6
|
|
|
use IBufferingStatsdDataFactory; |
|
7
|
|
|
use MWHttpRequest; |
|
8
|
|
|
use Psr\Log\LoggerInterface; |
|
9
|
|
|
use Wikibase\DataModel\Entity\EntityId; |
|
10
|
|
|
use WikibaseQuality\ConstraintReport\Constraint; |
|
11
|
|
|
use WikibaseQuality\ConstraintReport\ConstraintCheck\Context\Context; |
|
12
|
|
|
use WikibaseQuality\ConstraintReport\ConstraintCheck\Result\CheckResult; |
|
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
|
|
|
isset( $limit ) && $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
|
|
|
list( $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
|
|
|
'resultParameters' => json_encode( $result->getParameters() ), |
|
163
|
|
|
'resultMessage' => $resultMessageKey, |
|
164
|
|
|
] |
|
165
|
|
|
); |
|
166
|
|
|
} |
|
167
|
|
|
|
|
168
|
|
|
/** |
|
169
|
|
|
* Log a full constraint check on an entity. |
|
170
|
|
|
* The constraint check is tracked on the statsd data factory, |
|
171
|
|
|
* and also logged with the logger interface if it took longer than a certain time. |
|
172
|
|
|
* Multiple limits corresponding to different log levels can be specified in the configuration; |
|
173
|
|
|
* checks that exceed a higher limit are logged at a more severe level. |
|
174
|
|
|
* |
|
175
|
|
|
* |
|
176
|
|
|
* @param EntityId $entityId |
|
177
|
|
|
* @param CheckResult[] $checkResults |
|
178
|
|
|
* @param float $durationSeconds |
|
179
|
|
|
*/ |
|
180
|
|
|
public function logConstraintCheckOnEntity( |
|
181
|
|
|
EntityId $entityId, |
|
182
|
|
|
array $checkResults, |
|
|
|
|
|
|
183
|
|
|
$durationSeconds, |
|
184
|
|
|
$method |
|
185
|
|
|
) { |
|
186
|
|
|
$this->dataFactory->timing( |
|
187
|
|
|
'wikibase.quality.constraints.check.entity.timing', |
|
188
|
|
|
$durationSeconds * 1000 |
|
189
|
|
|
); |
|
190
|
|
|
|
|
191
|
|
|
// find the longest limit (and associated log level) that the duration exceeds |
|
192
|
|
|
list( $limitSeconds, $logLevel ) = $this->findLimit( |
|
193
|
|
|
$this->constraintCheckOnEntityDurationLimits, |
|
194
|
|
|
$durationSeconds |
|
195
|
|
|
); |
|
196
|
|
|
if ( $limitSeconds === null ) { |
|
197
|
|
|
return; |
|
198
|
|
|
} |
|
199
|
|
|
|
|
200
|
|
|
$this->logger->log( |
|
201
|
|
|
$logLevel, |
|
202
|
|
|
'Full constraint check on {entityId} ' . |
|
203
|
|
|
'took longer than {limitSeconds} second(s) ' . |
|
204
|
|
|
'(duration: {durationSeconds} seconds).', |
|
205
|
|
|
[ |
|
206
|
|
|
'method' => $method, |
|
207
|
|
|
'loggingMethod' => __METHOD__, |
|
208
|
|
|
'durationSeconds' => $durationSeconds, |
|
209
|
|
|
'limitSeconds' => $limitSeconds, |
|
210
|
|
|
'entityId' => $entityId->getSerialization(), |
|
211
|
|
|
// $checkResults currently not logged |
|
212
|
|
|
] |
|
213
|
|
|
); |
|
214
|
|
|
} |
|
215
|
|
|
|
|
216
|
|
|
/** |
|
217
|
|
|
* Log a cache hit for a complete constraint check result for the given entity ID. |
|
218
|
|
|
* |
|
219
|
|
|
* @param EntityId $entityId |
|
220
|
|
|
*/ |
|
221
|
|
|
public function logCheckConstraintsCacheHit( EntityId $entityId ) { |
|
|
|
|
|
|
222
|
|
|
$this->dataFactory->increment( |
|
223
|
|
|
'wikibase.quality.constraints.cache.entity.hit' |
|
224
|
|
|
); |
|
225
|
|
|
} |
|
226
|
|
|
|
|
227
|
|
|
/** |
|
228
|
|
|
* Log cache misses for a complete constraint check result for the given entity IDs. |
|
229
|
|
|
* |
|
230
|
|
|
* @param EntityId[] $entityIds |
|
231
|
|
|
*/ |
|
232
|
|
|
public function logCheckConstraintsCacheMisses( array $entityIds ) { |
|
233
|
|
|
$this->dataFactory->updateCount( |
|
234
|
|
|
'wikibase.quality.constraints.cache.entity.miss', |
|
235
|
|
|
count( $entityIds ) |
|
236
|
|
|
); |
|
237
|
|
|
} |
|
238
|
|
|
|
|
239
|
|
|
/** |
|
240
|
|
|
* Log that the dependency metadata for a check result had an empty set of entity IDs. |
|
241
|
|
|
* This should never happen – at least the entity being checked should always be contained. |
|
242
|
|
|
*/ |
|
243
|
|
|
public function logEmptyDependencyMetadata() { |
|
244
|
|
|
$this->logger->log( |
|
245
|
|
|
'warning', |
|
246
|
|
|
'Dependency metadata for constraint check result had empty set of entity IDs.', |
|
247
|
|
|
[ |
|
248
|
|
|
'loggingMethod' => __METHOD__, |
|
249
|
|
|
// callers of this method don’t have much information to pass to us, |
|
250
|
|
|
// so for now we don’t log any other structured data |
|
251
|
|
|
// and hope that the request URL provides enough information |
|
252
|
|
|
] |
|
253
|
|
|
); |
|
254
|
|
|
} |
|
255
|
|
|
|
|
256
|
|
|
/** |
|
257
|
|
|
* Log that the dependency metadata for a check result has a very large set of entity IDs. |
|
258
|
|
|
* |
|
259
|
|
|
* @param EntityId[] $entityIds |
|
260
|
|
|
* @param int $maxRevisionIds |
|
261
|
|
|
*/ |
|
262
|
|
|
public function logHugeDependencyMetadata( array $entityIds, $maxRevisionIds ) { |
|
263
|
|
|
$this->logger->log( |
|
264
|
|
|
'warning', |
|
265
|
|
|
'Dependency metadata for constraint check result has huge set of entity IDs ' . |
|
266
|
|
|
'(count ' . count( $entityIds ) . ', limit ' . $maxRevisionIds . '); ' . |
|
267
|
|
|
'caching disabled for this check result.', |
|
268
|
|
|
[ |
|
269
|
|
|
'loggingMethod' => __METHOD__, |
|
270
|
|
|
'entityIds' => json_encode( |
|
271
|
|
|
array_map( |
|
272
|
|
|
function ( EntityId $entityId ) { |
|
273
|
|
|
return $entityId->getSerialization(); |
|
274
|
|
|
}, |
|
275
|
|
|
$entityIds |
|
276
|
|
|
) |
|
277
|
|
|
), |
|
278
|
|
|
'maxRevisionIds' => $maxRevisionIds, |
|
279
|
|
|
] |
|
280
|
|
|
); |
|
281
|
|
|
} |
|
282
|
|
|
|
|
283
|
|
|
public function logSparqlHelperTooManyRequestsRetryAfterPresent( ConvertibleTimestamp $retryAfterTime, MWHttpRequest $request ) { |
|
284
|
|
|
$this->logger->notice( |
|
285
|
|
|
'Sparql API replied with status 429 and a retry-after header. Requesting to retry after {retryAfterTime}', |
|
286
|
|
|
[ |
|
287
|
|
|
'retryAfterTime' => $retryAfterTime, |
|
288
|
|
|
'responseHeaders' => json_encode( $request->getResponseHeaders() ), |
|
289
|
|
|
'responseContent' => $request->getContent(), |
|
290
|
|
|
] |
|
291
|
|
|
); |
|
292
|
|
|
} |
|
293
|
|
|
|
|
294
|
|
|
public function logSparqlHelperTooManyRequestsRetryAfterInvalid( MWHttpRequest $request ) { |
|
295
|
|
|
$this->logger->warning( |
|
296
|
|
|
'Sparql API replied with status 429 and no valid retry-after header.', |
|
297
|
|
|
[ |
|
298
|
|
|
'responseHeaders' => json_encode( $request->getResponseHeaders() ), |
|
299
|
|
|
'responseContent' => $request->getContent(), |
|
300
|
|
|
] |
|
301
|
|
|
); |
|
302
|
|
|
} |
|
303
|
|
|
|
|
304
|
|
|
} |
|
305
|
|
|
|
This check looks for PHPDoc comments describing methods or function parameters that do not exist on the corresponding method or function. It has, however, found a similar but not annotated parameter which might be a good fit.
Consider the following example. The parameter
$irelandis not defined by the methodfinale(...).The most likely cause is that the parameter was changed, but the annotation was not.