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