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.commons.logging.Log;
050import org.apache.commons.logging.LogFactory;
051import org.jboss.el.ExpressionFactoryImpl;
052import org.nuxeo.ecm.core.api.CloseableCoreSession;
053import org.nuxeo.ecm.core.api.CoreInstance;
054import org.nuxeo.ecm.core.api.CoreSession;
055import org.nuxeo.ecm.core.api.DocumentModel;
056import org.nuxeo.ecm.core.api.DocumentModelList;
057import org.nuxeo.ecm.core.api.DocumentNotFoundException;
058import org.nuxeo.ecm.core.api.DocumentRef;
059import org.nuxeo.ecm.core.api.LifeCycleConstants;
060import org.nuxeo.ecm.core.api.NuxeoException;
061import org.nuxeo.ecm.core.api.NuxeoPrincipal;
062import org.nuxeo.ecm.core.api.PathRef;
063import org.nuxeo.ecm.core.api.PropertyException;
064import org.nuxeo.ecm.core.api.ScrollResult;
065import org.nuxeo.ecm.core.api.event.DocumentEventTypes;
066import org.nuxeo.ecm.core.api.security.SecurityConstants;
067import org.nuxeo.ecm.core.event.DeletedDocumentModel;
068import org.nuxeo.ecm.core.event.Event;
069import org.nuxeo.ecm.core.event.EventBundle;
070import org.nuxeo.ecm.core.event.EventContext;
071import org.nuxeo.ecm.core.event.impl.DocumentEventContext;
072import org.nuxeo.ecm.core.query.sql.model.Operator;
073import org.nuxeo.ecm.core.query.sql.model.Predicate;
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.api.OrderByExprs;
080import org.nuxeo.ecm.platform.audit.api.Predicates;
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 Log log = LogFactory.getLog(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: " + exp + " on a DeletedDocumentModel, skipping.");
216                    }
217                    continue;
218                } catch (DocumentNotFoundException e) {
219                    if (!DocumentEventTypes.DOCUMENT_REMOVED.equals(entry.getEventId())) {
220                        log.error(String.format("Not found: %s, entry: %s", 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            Principal 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                String principalName;
272                if (principal instanceof NuxeoPrincipal) {
273                    principalName = ((NuxeoPrincipal) principal).getActingUser();
274                } else {
275                    principalName = principal.getName();
276                }
277                entry.setPrincipalName(principalName);
278            } else {
279                log.warn("received event " + eventName + " with null principal");
280            }
281            entry.setComment((String) properties.get("comment"));
282            if (document instanceof DeletedDocumentModel) {
283                entry.setComment("Document does not exist anymore!");
284            } else {
285                if (document.isLifeCycleLoaded()) {
286                    entry.setDocLifeCycle(document.getCurrentLifeCycleState());
287                }
288            }
289            if (LifeCycleConstants.TRANSITION_EVENT.equals(eventName)) {
290                entry.setDocLifeCycle((String) docCtx.getProperty(LifeCycleConstants.TRANSTION_EVENT_OPTION_TO));
291            }
292            String category = (String) properties.get("category");
293            if (category != null) {
294                entry.setCategory(category);
295            } else {
296                entry.setCategory("eventDocumentCategory");
297            }
298
299            doPutExtendedInfos(entry, docCtx, document, principal);
300
301        } else {
302            Principal principal = ctx.getPrincipal();
303            Map<String, Serializable> properties = ctx.getProperties();
304
305            if (principal != null) {
306                String principalName;
307                if (principal instanceof NuxeoPrincipal) {
308                    principalName = ((NuxeoPrincipal) principal).getActingUser();
309                } else {
310                    principalName = principal.getName();
311                }
312                entry.setPrincipalName(principalName);
313            }
314            entry.setComment((String) properties.get("comment"));
315
316            String category = (String) properties.get("category");
317            entry.setCategory(category);
318
319            doPutExtendedInfos(entry, ctx, null, principal);
320
321        }
322
323        return entry;
324    }
325
326    @Override
327    public LogEntry newLogEntry() {
328        return new LogEntryImpl();
329    }
330
331    @Override
332    public abstract ExtendedInfo newExtendedInfo(Serializable value);
333
334    protected long syncLogCreationEntries(BaseLogEntryProvider provider, String repoId, String path, Boolean recurs) {
335
336        provider.removeEntries(DocumentEventTypes.DOCUMENT_CREATED, path);
337        try (CloseableCoreSession session = CoreInstance.openCoreSession(repoId)) {
338            DocumentRef rootRef = new PathRef(path);
339            DocumentModel root = guardedDocument(session, rootRef);
340            long nbAddedEntries = doSyncNode(provider, session, root, recurs);
341
342            if (log.isDebugEnabled()) {
343                log.debug("synced " + nbAddedEntries + " entries on " + path);
344            }
345
346            return nbAddedEntries;
347        }
348    }
349
350    protected long doSyncNode(BaseLogEntryProvider provider, CoreSession session, DocumentModel node, boolean recurs) {
351
352        long nbSyncedEntries = 1;
353
354        Principal principal = session.getPrincipal();
355        List<DocumentModel> folderishChildren = new ArrayList<>();
356
357        provider.addLogEntry(doCreateAndFillEntryFromDocument(node, session.getPrincipal()));
358
359        for (DocumentModel child : guardedDocumentChildren(session, node.getRef())) {
360            if (child.isFolder() && recurs) {
361                folderishChildren.add(child);
362            } else {
363                provider.addLogEntry(doCreateAndFillEntryFromDocument(child, principal));
364                nbSyncedEntries += 1;
365            }
366        }
367
368        if (recurs) {
369            for (DocumentModel folderChild : folderishChildren) {
370                nbSyncedEntries += doSyncNode(provider, session, folderChild, recurs);
371            }
372        }
373
374        return nbSyncedEntries;
375    }
376
377    @Override
378    public void logEvents(EventBundle bundle) {
379        if (!isAuditable(bundle)) {
380            return;
381        }
382        for (Event event : bundle) {
383            logEvent(event);
384        }
385    }
386
387    protected boolean isAuditable(EventBundle eventBundle) {
388        for (String name : getAuditableEventNames()) {
389            if (eventBundle.containsEventName(name)) {
390                return true;
391            }
392        }
393        return false;
394    }
395
396    @Override
397    public void logEvent(Event event) {
398        if (!getAuditableEventNames().contains(event.getName())) {
399            return;
400        }
401        LogEntry entry = buildEntryFromEvent(event);
402        if (entry == null) {
403            return;
404        }
405        component.bulker.offer(entry);
406    }
407
408    @Override
409    public boolean await(long time, TimeUnit unit) throws InterruptedException {
410        if (Framework.isBooleanPropertyTrue(STREAM_AUDIT_ENABLED_PROP)) {
411            StreamService service = Framework.getService(StreamService.class);
412            LogManager logManager = service.getLogManager(DEFAULT_LOG_CONFIG);
413            // when there is no lag between producer and consumer we are done
414            long deadline = System.currentTimeMillis() + unit.toMillis(time);
415            while (logManager.getLag(STREAM_NAME, COMPUTATION_NAME).lag() > 0) {
416                if (System.currentTimeMillis() > deadline) {
417                    return false;
418                }
419                Thread.sleep(50);
420            }
421            return true;
422        } else {
423            return component.bulker.await(time, unit);
424        }
425    }
426
427    @Override
428    @Deprecated
429    public List<LogEntry> getLogEntriesFor(String uuid, Map<String, FilterMapEntry> filterMap, boolean doDefaultSort) {
430        // create builder
431        AuditQueryBuilder builder = new AuditQueryBuilder();
432        // create predicates
433        builder.addAndPredicate(Predicates.eq(LOG_DOC_UUID, uuid));
434        filterMap.values().stream().map(this::convert).forEach(builder::addAndPredicate);
435        if (doDefaultSort) {
436            builder.defaultOrder();
437        }
438        return queryLogs(builder);
439    }
440
441    protected Predicate convert(FilterMapEntry entry) {
442        String name = entry.getColumnName();
443        String operator = entry.getOperator();
444        Object value = entry.getObject();
445        if (Operator.EQ.toString().equals(operator)) {
446            return Predicates.eq(name, value);
447        } else if (Operator.LT.toString().equals(operator)) {
448            return Predicates.lt(name, value);
449        } else if (Operator.LTEQ.toString().equals(operator)) {
450            return Predicates.lte(name, value);
451        } else if (Operator.GTEQ.toString().equals(operator)) {
452            return Predicates.gte(name, value);
453        } else if (Operator.GT.toString().equals(operator)) {
454            return Predicates.gt(name, value);
455        } else if (Operator.IN.toString().equals(operator)) {
456            return Predicates.in(name, (List<?>) value);
457        }
458        throw new NuxeoException(String.format("Audit backend search doesn't handle '%s' operator", operator));
459    }
460
461    @Override
462    public List<LogEntry> queryLogsByPage(String[] eventIds, Date limit, String[] categories, String path, int pageNb,
463            int pageSize) {
464        AuditQueryBuilder builder = new AuditQueryBuilder();
465        if (ArrayUtils.isNotEmpty(eventIds)) {
466            if (eventIds.length == 1) {
467                builder.addAndPredicate(Predicates.eq(LOG_EVENT_ID, eventIds[0]));
468            } else {
469                builder.addAndPredicate(Predicates.in(LOG_EVENT_ID, eventIds[0]));
470            }
471        }
472        if (ArrayUtils.isNotEmpty(categories)) {
473            if (categories.length == 1) {
474                builder.addAndPredicate(Predicates.eq(LOG_CATEGORY, categories[0]));
475            } else {
476                builder.addAndPredicate(Predicates.in(LOG_CATEGORY, categories[0]));
477            }
478        }
479        if (path != null) {
480            builder.addAndPredicate(Predicates.eq(LOG_DOC_PATH, path));
481        }
482        if (limit != null) {
483            builder.addAndPredicate(Predicates.lt(LOG_EVENT_DATE, limit));
484        }
485        builder.offset(pageNb * pageSize).limit(pageSize);
486        return queryLogs(builder);
487    }
488
489    @Override
490    public long getLatestLogId(String repositoryId, String... eventIds) {
491        AuditQueryBuilder builder = new AuditQueryBuilder().addAndPredicate(
492                Predicates.eq(LOG_REPOSITORY_ID, repositoryId))
493                                                           .addAndPredicate(Predicates.in(LOG_EVENT_ID, eventIds))
494                                                           .order(OrderByExprs.desc(LOG_ID))
495                                                           .limit(1);
496        return queryLogs(builder).stream().mapToLong(LogEntry::getId).findFirst().orElse(0L);
497    }
498
499    @Override
500    public List<LogEntry> getLogEntriesAfter(long logIdOffset, int limit, String repositoryId, String... eventIds) {
501        AuditQueryBuilder builder = new AuditQueryBuilder().addAndPredicate(
502                Predicates.eq(LOG_REPOSITORY_ID, repositoryId))
503                                                           .addAndPredicate(Predicates.in(LOG_EVENT_ID, eventIds))
504                                                           .addAndPredicate(Predicates.gte(LOG_ID, logIdOffset))
505                                                           .order(OrderByExprs.asc(LOG_ID))
506                                                           .limit(limit);
507        return queryLogs(builder);
508    }
509
510    @Override
511    public void restore(AuditStorage auditStorage, int batchSize, int keepAlive) {
512
513        AuditQueryBuilder builder = new AuditQueryBuilder();
514        ScrollResult<String> scrollResult = auditStorage.scroll(builder, batchSize, keepAlive);
515        long t0 = System.currentTimeMillis();
516        int total = 0;
517
518        log.info("Starting audit restoration");
519
520        while (scrollResult.hasResults()) {
521            List<String> jsonEntries = scrollResult.getResults();
522            if (log.isDebugEnabled()) {
523                log.debug("Appending " + jsonEntries.size() + " entries");
524            }
525            total += jsonEntries.size();
526            append(jsonEntries);
527
528            double dt = (System.currentTimeMillis() - t0) / 1000.0;
529            if (dt != 0) {
530                if (log.isDebugEnabled()) {
531                    log.debug("Restoration speed: " + (total / dt) + " entries/s");
532                }
533            }
534
535            scrollResult = auditStorage.scroll(scrollResult.getScrollId());
536        }
537
538        log.info("Audit restoration done: " + total + " entries migrated from the audit storage");
539
540    }
541
542}