001/* 002 * (C) Copyright 2006-2017 Nuxeo (http://nuxeo.com/) and others. 003 * 004 * Licensed under the Apache License, Version 2.0 (the "License"); 005 * you may not use this file except in compliance with the License. 006 * You may obtain a copy of the License at 007 * 008 * http://www.apache.org/licenses/LICENSE-2.0 009 * 010 * Unless required by applicable law or agreed to in writing, software 011 * distributed under the License is distributed on an "AS IS" BASIS, 012 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 013 * See the License for the specific language governing permissions and 014 * limitations under the License. 015 * 016 * Contributors: 017 * Thierry Delprat 018 */ 019package org.nuxeo.ecm.platform.audit.service; 020 021import static org.nuxeo.ecm.core.schema.FacetNames.SYSTEM_DOCUMENT; 022import static org.nuxeo.ecm.platform.audit.api.BuiltinLogEntryData.LOG_CATEGORY; 023import static org.nuxeo.ecm.platform.audit.api.BuiltinLogEntryData.LOG_DOC_PATH; 024import static org.nuxeo.ecm.platform.audit.api.BuiltinLogEntryData.LOG_DOC_UUID; 025import static org.nuxeo.ecm.platform.audit.api.BuiltinLogEntryData.LOG_EVENT_DATE; 026import static org.nuxeo.ecm.platform.audit.api.BuiltinLogEntryData.LOG_EVENT_ID; 027import static org.nuxeo.ecm.platform.audit.api.BuiltinLogEntryData.LOG_ID; 028import static org.nuxeo.ecm.platform.audit.api.BuiltinLogEntryData.LOG_REPOSITORY_ID; 029import static org.nuxeo.ecm.platform.audit.impl.StreamAuditWriter.COMPUTATION_NAME; 030import static org.nuxeo.ecm.platform.audit.listener.StreamAuditEventListener.DEFAULT_LOG_CONFIG; 031import static org.nuxeo.ecm.platform.audit.listener.StreamAuditEventListener.STREAM_AUDIT_ENABLED_PROP; 032import static org.nuxeo.ecm.platform.audit.listener.StreamAuditEventListener.STREAM_NAME; 033 034import java.io.Serializable; 035import java.security.Principal; 036import java.util.ArrayList; 037import java.util.Calendar; 038import java.util.Collection; 039import java.util.Date; 040import java.util.List; 041import java.util.Map; 042import java.util.Map.Entry; 043import java.util.Set; 044import java.util.concurrent.TimeUnit; 045 046import javax.el.ELException; 047 048import org.apache.commons.lang3.ArrayUtils; 049import org.apache.logging.log4j.Logger; 050import org.jboss.el.ExpressionFactoryImpl; 051import org.nuxeo.ecm.core.api.CloseableCoreSession; 052import org.nuxeo.ecm.core.api.CoreInstance; 053import org.nuxeo.ecm.core.api.CoreSession; 054import org.nuxeo.ecm.core.api.DocumentModel; 055import org.nuxeo.ecm.core.api.DocumentModelList; 056import org.nuxeo.ecm.core.api.DocumentNotFoundException; 057import org.nuxeo.ecm.core.api.DocumentRef; 058import org.nuxeo.ecm.core.api.LifeCycleConstants; 059import org.nuxeo.ecm.core.api.NuxeoException; 060import org.nuxeo.ecm.core.api.NuxeoPrincipal; 061import org.nuxeo.ecm.core.api.PathRef; 062import org.nuxeo.ecm.core.api.PropertyException; 063import org.nuxeo.ecm.core.api.ScrollResult; 064import org.nuxeo.ecm.core.api.event.DocumentEventTypes; 065import org.nuxeo.ecm.core.api.security.SecurityConstants; 066import org.nuxeo.ecm.core.event.DeletedDocumentModel; 067import org.nuxeo.ecm.core.event.Event; 068import org.nuxeo.ecm.core.event.EventBundle; 069import org.nuxeo.ecm.core.event.EventContext; 070import org.nuxeo.ecm.core.event.impl.DocumentEventContext; 071import org.nuxeo.ecm.core.query.sql.model.Operator; 072import org.nuxeo.ecm.core.query.sql.model.OrderByExprs; 073import org.nuxeo.ecm.core.query.sql.model.Predicate; 074import org.nuxeo.ecm.core.query.sql.model.Predicates; 075import org.nuxeo.ecm.core.query.sql.model.QueryBuilder; 076import org.nuxeo.ecm.platform.audit.api.AuditQueryBuilder; 077import org.nuxeo.ecm.platform.audit.api.AuditStorage; 078import org.nuxeo.ecm.platform.audit.api.ExtendedInfo; 079import org.nuxeo.ecm.platform.audit.api.FilterMapEntry; 080import org.nuxeo.ecm.platform.audit.api.LogEntry; 081import org.nuxeo.ecm.platform.audit.impl.LogEntryImpl; 082import org.nuxeo.ecm.platform.audit.service.extension.AdapterDescriptor; 083import org.nuxeo.ecm.platform.audit.service.extension.AuditBackendDescriptor; 084import org.nuxeo.ecm.platform.audit.service.extension.ExtendedInfoDescriptor; 085import org.nuxeo.ecm.platform.el.ExpressionContext; 086import org.nuxeo.ecm.platform.el.ExpressionEvaluator; 087import org.nuxeo.lib.stream.log.LogManager; 088import org.nuxeo.runtime.api.Framework; 089import org.nuxeo.runtime.stream.StreamService; 090 091/** 092 * Abstract class to share code between {@link AuditBackend} implementations 093 * 094 * @author tiry 095 */ 096public abstract class AbstractAuditBackend implements AuditBackend, AuditStorage { 097 098 protected static final Logger log = org.apache.logging.log4j.LogManager.getLogger(AbstractAuditBackend.class); 099 100 public static final String FORCE_AUDIT_FACET = "ForceAudit"; 101 102 protected final NXAuditEventsService component; 103 104 protected final AuditBackendDescriptor config; 105 106 protected AbstractAuditBackend(NXAuditEventsService component, AuditBackendDescriptor config) { 107 this.component = component; 108 this.config = config; 109 } 110 111 protected AbstractAuditBackend() { 112 this(null, null); 113 } 114 115 protected final ExpressionEvaluator expressionEvaluator = new ExpressionEvaluator(new ExpressionFactoryImpl()); 116 117 protected DocumentModel guardedDocument(CoreSession session, DocumentRef reference) { 118 if (session == null) { 119 return null; 120 } 121 if (reference == null) { 122 return null; 123 } 124 try { 125 return session.getDocument(reference); 126 } catch (DocumentNotFoundException e) { 127 return null; 128 } 129 } 130 131 protected DocumentModelList guardedDocumentChildren(CoreSession session, DocumentRef reference) { 132 return session.getChildren(reference); 133 } 134 135 protected LogEntry doCreateAndFillEntryFromDocument(DocumentModel doc, Principal principal) { 136 LogEntry entry = newLogEntry(); 137 entry.setDocPath(doc.getPathAsString()); 138 entry.setDocType(doc.getType()); 139 entry.setDocUUID(doc.getId()); 140 entry.setRepositoryId(doc.getRepositoryName()); 141 entry.setPrincipalName(SecurityConstants.SYSTEM_USERNAME); 142 entry.setCategory("eventDocumentCategory"); 143 entry.setEventId(DocumentEventTypes.DOCUMENT_CREATED); 144 // why hard-code it if we have the document life cycle? 145 entry.setDocLifeCycle("project"); 146 Calendar creationDate = (Calendar) doc.getProperty("dublincore", "created"); 147 if (creationDate != null) { 148 entry.setEventDate(creationDate.getTime()); 149 } 150 151 doPutExtendedInfos(entry, null, doc, principal); 152 153 return entry; 154 } 155 156 protected void doPutExtendedInfos(LogEntry entry, EventContext eventContext, DocumentModel source, 157 Principal principal) { 158 159 ExpressionContext context = new ExpressionContext(); 160 if (eventContext != null) { 161 expressionEvaluator.bindValue(context, "message", eventContext); 162 } 163 if (source != null) { 164 expressionEvaluator.bindValue(context, "source", source); 165 // inject now the adapters 166 for (AdapterDescriptor ad : component.getDocumentAdapters()) { 167 if (source instanceof DeletedDocumentModel) { 168 continue; // skip 169 } 170 Object adapter = source.getAdapter(ad.getKlass()); 171 if (adapter != null) { 172 expressionEvaluator.bindValue(context, ad.getName(), adapter); 173 } 174 } 175 } 176 if (principal != null) { 177 expressionEvaluator.bindValue(context, "principal", principal); 178 } 179 180 // Global extended info 181 populateExtendedInfo(entry, source, context, component.getExtendedInfoDescriptors()); 182 // Event id related extended info 183 populateExtendedInfo(entry, source, context, 184 component.getEventExtendedInfoDescriptors().get(entry.getEventId())); 185 186 if (eventContext != null) { 187 @SuppressWarnings("unchecked") 188 Map<String, Serializable> map = (Map<String, Serializable>) eventContext.getProperty("extendedInfos"); 189 if (map != null) { 190 Map<String, ExtendedInfo> extendedInfos = entry.getExtendedInfos(); 191 for (Entry<String, Serializable> en : map.entrySet()) { 192 Serializable value = en.getValue(); 193 if (value != null) { 194 extendedInfos.put(en.getKey(), newExtendedInfo(value)); 195 } 196 } 197 } 198 } 199 } 200 201 /** 202 * @since 7.4 203 */ 204 protected void populateExtendedInfo(LogEntry entry, DocumentModel source, ExpressionContext context, 205 Collection<ExtendedInfoDescriptor> extInfos) { 206 if (extInfos != null) { 207 Map<String, ExtendedInfo> extendedInfos = entry.getExtendedInfos(); 208 for (ExtendedInfoDescriptor descriptor : extInfos) { 209 String exp = descriptor.getExpression(); 210 Serializable value; 211 try { 212 value = expressionEvaluator.evaluateExpression(context, exp, Serializable.class); 213 } catch (PropertyException | UnsupportedOperationException e) { 214 if (source instanceof DeletedDocumentModel) { 215 log.debug("Can not evaluate the expression: {} on a DeletedDocumentModel, skipping.", exp); 216 } 217 continue; 218 } catch (DocumentNotFoundException e) { 219 if (!DocumentEventTypes.DOCUMENT_REMOVED.equals(entry.getEventId())) { 220 log.error("Not found: {}, entry: {}", e.getMessage(), entry, e); 221 } 222 continue; 223 } catch (ELException e) { 224 continue; 225 } 226 if (value == null) { 227 continue; 228 } 229 extendedInfos.put(descriptor.getKey(), newExtendedInfo(value)); 230 } 231 } 232 } 233 234 @Override 235 public Set<String> getAuditableEventNames() { 236 return component.getAuditableEventNames(); 237 } 238 239 @Override 240 public LogEntry buildEntryFromEvent(Event event) { 241 EventContext ctx = event.getContext(); 242 String eventName = event.getName(); 243 Date eventDate = new Date(event.getTime()); 244 245 LogEntry entry = newLogEntry(); 246 entry.setEventId(eventName); 247 entry.setEventDate(eventDate); 248 249 if (ctx instanceof DocumentEventContext) { 250 DocumentEventContext docCtx = (DocumentEventContext) ctx; 251 DocumentModel document = docCtx.getSourceDocument(); 252 if (document.hasFacet(SYSTEM_DOCUMENT) && !document.hasFacet(FORCE_AUDIT_FACET)) { 253 // do not log event on System documents 254 // unless it has the FORCE_AUDIT_FACET facet 255 return null; 256 } 257 258 Boolean disabled = (Boolean) docCtx.getProperty(NXAuditEventsService.DISABLE_AUDIT_LOGGER); 259 if (disabled != null && disabled.booleanValue()) { 260 // don't log events with this flag 261 return null; 262 } 263 NuxeoPrincipal principal = docCtx.getPrincipal(); 264 Map<String, Serializable> properties = docCtx.getProperties(); 265 266 entry.setDocUUID(document.getId()); 267 entry.setDocPath(document.getPathAsString()); 268 entry.setDocType(document.getType()); 269 entry.setRepositoryId(document.getRepositoryName()); 270 if (principal != null) { 271 entry.setPrincipalName(principal.getActingUser()); 272 } else { 273 log.warn("received event {} with null principal", eventName); 274 } 275 entry.setComment((String) properties.get("comment")); 276 if (document instanceof DeletedDocumentModel) { 277 entry.setComment("Document does not exist anymore!"); 278 } else { 279 if (document.isLifeCycleLoaded()) { 280 entry.setDocLifeCycle(document.getCurrentLifeCycleState()); 281 } 282 } 283 if (LifeCycleConstants.TRANSITION_EVENT.equals(eventName)) { 284 entry.setDocLifeCycle((String) docCtx.getProperty(LifeCycleConstants.TRANSTION_EVENT_OPTION_TO)); 285 } 286 String category = (String) properties.get("category"); 287 if (category != null) { 288 entry.setCategory(category); 289 } else { 290 entry.setCategory("eventDocumentCategory"); 291 } 292 293 doPutExtendedInfos(entry, docCtx, document, principal); 294 295 } else { 296 NuxeoPrincipal principal = ctx.getPrincipal(); 297 Map<String, Serializable> properties = ctx.getProperties(); 298 299 if (principal != null) { 300 entry.setPrincipalName(principal.getActingUser()); 301 } 302 entry.setComment((String) properties.get("comment")); 303 304 String category = (String) properties.get("category"); 305 entry.setCategory(category); 306 307 doPutExtendedInfos(entry, ctx, null, principal); 308 309 } 310 311 return entry; 312 } 313 314 @Override 315 public LogEntry newLogEntry() { 316 return new LogEntryImpl(); 317 } 318 319 @Override 320 public abstract ExtendedInfo newExtendedInfo(Serializable value); 321 322 protected long syncLogCreationEntries(BaseLogEntryProvider provider, String repoId, String path, Boolean recurs) { 323 324 provider.removeEntries(DocumentEventTypes.DOCUMENT_CREATED, path); 325 try (CloseableCoreSession session = CoreInstance.openCoreSession(repoId)) { 326 DocumentRef rootRef = new PathRef(path); 327 DocumentModel root = guardedDocument(session, rootRef); 328 long nbAddedEntries = doSyncNode(provider, session, root, recurs); 329 330 log.debug("synced {} entries on {}", nbAddedEntries, path); 331 return nbAddedEntries; 332 } 333 } 334 335 protected long doSyncNode(BaseLogEntryProvider provider, CoreSession session, DocumentModel node, boolean recurs) { 336 337 long nbSyncedEntries = 1; 338 339 NuxeoPrincipal principal = session.getPrincipal(); 340 List<DocumentModel> folderishChildren = new ArrayList<>(); 341 342 provider.addLogEntry(doCreateAndFillEntryFromDocument(node, session.getPrincipal())); 343 344 for (DocumentModel child : guardedDocumentChildren(session, node.getRef())) { 345 if (child.isFolder() && recurs) { 346 folderishChildren.add(child); 347 } else { 348 provider.addLogEntry(doCreateAndFillEntryFromDocument(child, principal)); 349 nbSyncedEntries += 1; 350 } 351 } 352 353 if (recurs) { 354 for (DocumentModel folderChild : folderishChildren) { 355 nbSyncedEntries += doSyncNode(provider, session, folderChild, recurs); 356 } 357 } 358 359 return nbSyncedEntries; 360 } 361 362 @Override 363 @Deprecated 364 public void logEvents(EventBundle bundle) { 365 if (!isAuditable(bundle)) { 366 return; 367 } 368 for (Event event : bundle) { 369 logEvent(event); 370 } 371 } 372 373 protected boolean isAuditable(EventBundle eventBundle) { 374 for (String name : getAuditableEventNames()) { 375 if (eventBundle.containsEventName(name)) { 376 return true; 377 } 378 } 379 return false; 380 } 381 382 @Override 383 @Deprecated 384 public void logEvent(Event event) { 385 if (!getAuditableEventNames().contains(event.getName())) { 386 return; 387 } 388 LogEntry entry = buildEntryFromEvent(event); 389 if (entry == null) { 390 return; 391 } 392 if (Framework.isBooleanPropertyFalse(STREAM_AUDIT_ENABLED_PROP)) { 393 component.bulker.offer(entry); 394 } else { 395 log.error("Usage of AuditLogger#logEvent while AuditBulker is disabled", new Exception()); 396 } 397 } 398 399 @Override 400 public boolean await(long time, TimeUnit unit) throws InterruptedException { 401 if (Framework.isBooleanPropertyFalse(STREAM_AUDIT_ENABLED_PROP)) { 402 return component.bulker.await(time, unit); 403 } else { 404 StreamService service = Framework.getService(StreamService.class); 405 LogManager logManager = service.getLogManager(DEFAULT_LOG_CONFIG); 406 // when there is no lag between producer and consumer we are done 407 long deadline = System.currentTimeMillis() + unit.toMillis(time); 408 while (logManager.getLag(STREAM_NAME, COMPUTATION_NAME).lag() > 0) { 409 if (System.currentTimeMillis() > deadline) { 410 return false; 411 } 412 Thread.sleep(50); 413 } 414 return true; 415 } 416 } 417 418 @Override 419 @Deprecated 420 public List<LogEntry> getLogEntriesFor(String uuid, Map<String, FilterMapEntry> filterMap, boolean doDefaultSort) { 421 // create builder 422 QueryBuilder builder = new AuditQueryBuilder(); 423 // create predicates 424 builder.predicate(Predicates.eq(LOG_DOC_UUID, uuid)); 425 filterMap.values().stream().map(this::convert).forEach(builder::and); 426 if (doDefaultSort) { 427 builder.defaultOrder(); 428 } 429 return queryLogs(builder); 430 } 431 432 protected Predicate convert(FilterMapEntry entry) { 433 String name = entry.getColumnName(); 434 String operator = entry.getOperator(); 435 Object value = entry.getObject(); 436 if (Operator.EQ.toString().equals(operator)) { 437 return Predicates.eq(name, value); 438 } else if (Operator.LT.toString().equals(operator)) { 439 return Predicates.lt(name, value); 440 } else if (Operator.LTEQ.toString().equals(operator)) { 441 return Predicates.lte(name, value); 442 } else if (Operator.GTEQ.toString().equals(operator)) { 443 return Predicates.gte(name, value); 444 } else if (Operator.GT.toString().equals(operator)) { 445 return Predicates.gt(name, value); 446 } else if (Operator.IN.toString().equals(operator)) { 447 return Predicates.in(name, (List<?>) value); 448 } 449 throw new NuxeoException(String.format("Audit backend search doesn't handle '%s' operator", operator)); 450 } 451 452 @Override 453 public List<LogEntry> queryLogsByPage(String[] eventIds, Date limit, String[] categories, String path, int pageNb, 454 int pageSize) { 455 QueryBuilder builder = new AuditQueryBuilder(); 456 if (ArrayUtils.isNotEmpty(eventIds)) { 457 if (eventIds.length == 1) { 458 builder.predicate(Predicates.eq(LOG_EVENT_ID, eventIds[0])); 459 } else { 460 builder.predicate(Predicates.in(LOG_EVENT_ID, eventIds[0])); 461 } 462 } 463 if (ArrayUtils.isNotEmpty(categories)) { 464 if (categories.length == 1) { 465 builder.predicate(Predicates.eq(LOG_CATEGORY, categories[0])); 466 } else { 467 builder.predicate(Predicates.in(LOG_CATEGORY, categories[0])); 468 } 469 } 470 if (path != null) { 471 builder.predicate(Predicates.eq(LOG_DOC_PATH, path)); 472 } 473 if (limit != null) { 474 builder.predicate(Predicates.lt(LOG_EVENT_DATE, limit)); 475 } 476 builder.offset(pageNb * pageSize).limit(pageSize); 477 return queryLogs(builder); 478 } 479 480 @Override 481 public long getLatestLogId(String repositoryId, String... eventIds) { 482 QueryBuilder builder = new AuditQueryBuilder().predicate(Predicates.eq(LOG_REPOSITORY_ID, repositoryId)) 483 .and(Predicates.in(LOG_EVENT_ID, eventIds)) 484 .order(OrderByExprs.desc(LOG_ID)) 485 .limit(1); 486 return queryLogs(builder).stream().mapToLong(LogEntry::getId).findFirst().orElse(0L); 487 } 488 489 @Override 490 public List<LogEntry> getLogEntriesAfter(long logIdOffset, int limit, String repositoryId, String... eventIds) { 491 QueryBuilder builder = new AuditQueryBuilder().predicate(Predicates.eq(LOG_REPOSITORY_ID, repositoryId)) 492 .and(Predicates.in(LOG_EVENT_ID, eventIds)) 493 .and(Predicates.gte(LOG_ID, logIdOffset)) 494 .order(OrderByExprs.asc(LOG_ID)) 495 .limit(limit); 496 return queryLogs(builder); 497 } 498 499 @Override 500 public void restore(AuditStorage auditStorage, int batchSize, int keepAlive) { 501 502 QueryBuilder builder = new AuditQueryBuilder(); 503 ScrollResult<String> scrollResult = auditStorage.scroll(builder, batchSize, keepAlive); 504 long t0 = System.currentTimeMillis(); 505 int total = 0; 506 507 log.info("Starting audit restoration"); 508 509 while (scrollResult.hasResults()) { 510 List<String> jsonEntries = scrollResult.getResults(); 511 log.debug("Appending {} entries", jsonEntries::size); 512 total += jsonEntries.size(); 513 append(jsonEntries); 514 515 double dt = (System.currentTimeMillis() - t0) / 1000.0; 516 if (dt != 0) { 517 log.debug("Restoration speed: {} entries/s", total / dt); 518 } 519 520 scrollResult = auditStorage.scroll(scrollResult.getScrollId()); 521 } 522 523 log.info("Audit restoration done: {} entries migrated from the audit storage", total); 524 525 } 526 527}