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}