001/*
002 * The contents of this file are subject to the terms of the Common Development and
003 * Distribution License (the License). You may not use this file except in compliance with the
004 * License.
005 *
006 * You can obtain a copy of the License at legal/CDDLv1.0.txt. See the License for the
007 * specific language governing permission and limitations under the License.
008 *
009 * When distributing Covered Software, include this CDDL Header Notice in each file and include
010 * the License file at legal/CDDLv1.0.txt. If applicable, add the following below the CDDL
011 * Header, with the fields enclosed by brackets [] replaced by your own identifying
012 * information: "Portions Copyright [year] [name of copyright owner]".
013 *
014 * Copyright 2006-2009 Sun Microsystems, Inc.
015 * Portions Copyright 2011-2016 ForgeRock AS.
016 */
017package org.opends.server.loggers;
018
019import static org.opends.messages.LoggerMessages.ERR_COMMON_AUDIT_INVALID_TRANSACTION_ID;
020import static org.opends.messages.ConfigMessages.*;
021import static org.opends.server.util.StaticUtils.*;
022
023import java.io.File;
024import java.io.IOException;
025import java.text.SimpleDateFormat;
026import java.util.List;
027import java.util.Set;
028
029import org.forgerock.i18n.LocalizableMessage;
030import org.forgerock.i18n.LocalizableMessageBuilder;
031import org.forgerock.opendj.config.server.ConfigChangeResult;
032import org.forgerock.opendj.config.server.ConfigException;
033import org.forgerock.opendj.ldap.ByteString;
034import org.forgerock.opendj.ldap.DN;
035import org.forgerock.opendj.ldap.ResultCode;
036import org.forgerock.util.Utils;
037import org.forgerock.opendj.config.server.ConfigurationChangeListener;
038import org.forgerock.opendj.server.config.meta.FileBasedAccessLogPublisherCfgDefn.LogFormat;
039import org.forgerock.opendj.server.config.server.FileBasedAccessLogPublisherCfg;
040import org.opends.server.api.ClientConnection;
041import org.opends.server.api.ExtendedOperationHandler;
042import org.opends.server.controls.TransactionIdControl;
043import org.opends.server.core.AbandonOperation;
044import org.opends.server.core.AddOperation;
045import org.opends.server.core.BindOperation;
046import org.opends.server.core.CompareOperation;
047import org.opends.server.core.DeleteOperation;
048import org.opends.server.core.DirectoryServer;
049import org.opends.server.core.ExtendedOperation;
050import org.opends.server.core.ModifyDNOperation;
051import org.opends.server.core.ModifyOperation;
052import org.opends.server.core.SearchOperation;
053import org.opends.server.core.ServerContext;
054import org.opends.server.core.UnbindOperation;
055import org.opends.server.types.AdditionalLogItem;
056import org.opends.server.types.AuthenticationInfo;
057import org.opends.server.types.Control;
058import org.opends.server.types.DirectoryException;
059import org.opends.server.types.DisconnectReason;
060import org.opends.server.types.FilePermission;
061import org.opends.server.types.InitializationException;
062import org.opends.server.types.Operation;
063import org.opends.server.util.StaticUtils;
064import org.opends.server.util.TimeThread;
065
066/** This class provides the implementation of the access logger used by the directory server. */
067public final class TextAccessLogPublisher extends
068    AbstractTextAccessLogPublisher<FileBasedAccessLogPublisherCfg> implements
069    ConfigurationChangeListener<FileBasedAccessLogPublisherCfg>
070{
071  /** The category to use when logging responses. */
072  private static final String CATEGORY_RESPONSE = "RES";
073  /** The category to use when logging requests. */
074  private static final String CATEGORY_REQUEST = "REQ";
075
076  /**
077   * Returns an instance of the text access log publisher that will print all
078   * messages to the provided writer. This is used to print the messages to the
079   * console when the server starts up.
080   *
081   * @param writer
082   *          The text writer where the message will be written to.
083   * @param suppressInternal
084   *          Indicates whether to suppress internal operations.
085   * @return The instance of the text error log publisher that will print all
086   *         messages to standard out.
087   */
088  public static TextAccessLogPublisher getStartupTextAccessPublisher(
089      final TextWriter writer, final boolean suppressInternal)
090  {
091    final TextAccessLogPublisher startupPublisher = new TextAccessLogPublisher();
092    startupPublisher.writer = writer;
093    startupPublisher.buildFilters(suppressInternal);
094    return startupPublisher;
095  }
096
097  private TextWriter writer;
098  private FileBasedAccessLogPublisherCfg cfg;
099  private boolean isCombinedMode;
100  private boolean includeControlOIDs;
101  private String timeStampFormat = "dd/MMM/yyyy:HH:mm:ss Z";
102  private ServerContext serverContext;
103
104  @Override
105  public ConfigChangeResult applyConfigurationChange(FileBasedAccessLogPublisherCfg config)
106  {
107    final ConfigChangeResult ccr = new ConfigChangeResult();
108
109    try
110    {
111      // Determine the writer we are using. If we were writing asynchronously,
112      // we need to modify the underlying writer.
113      TextWriter currentWriter;
114      if (writer instanceof AsynchronousTextWriter)
115      {
116        currentWriter = ((AsynchronousTextWriter) writer).getWrappedWriter();
117      }
118      else
119      {
120        currentWriter = writer;
121      }
122
123      if (currentWriter instanceof MultifileTextWriter)
124      {
125        final MultifileTextWriter mfWriter = (MultifileTextWriter) currentWriter;
126        configure(mfWriter, config);
127
128        if (config.isAsynchronous())
129        {
130          if (writer instanceof AsynchronousTextWriter)
131          {
132            if (hasAsyncConfigChanged(config))
133            {
134              // reinstantiate
135              final AsynchronousTextWriter previousWriter = (AsynchronousTextWriter) writer;
136              writer = newAsyncWriter(mfWriter, config);
137              previousWriter.shutdown(false);
138            }
139          }
140          else
141          {
142            // turn async text writer on
143            writer = newAsyncWriter(mfWriter, config);
144          }
145        }
146        else
147        {
148          if (writer instanceof AsynchronousTextWriter)
149          {
150            // asynchronous is being turned off, remove async text writers.
151            final AsynchronousTextWriter previousWriter = (AsynchronousTextWriter) writer;
152            writer = mfWriter;
153            previousWriter.shutdown(false);
154          }
155        }
156
157        if (cfg.isAsynchronous() && config.isAsynchronous()
158            && cfg.getQueueSize() != config.getQueueSize())
159        {
160          ccr.setAdminActionRequired(true);
161        }
162
163        if (!config.getLogRecordTimeFormat().equals(timeStampFormat))
164        {
165          TimeThread.removeUserDefinedFormatter(timeStampFormat);
166          timeStampFormat = config.getLogRecordTimeFormat();
167        }
168
169        cfg = config;
170        isCombinedMode = cfg.getLogFormat() == LogFormat.COMBINED;
171        includeControlOIDs = cfg.isLogControlOids();
172      }
173    }
174    catch (final Exception e)
175    {
176      ccr.setResultCode(DirectoryServer.getServerErrorResultCode());
177      ccr.addMessage(ERR_CONFIG_LOGGING_CANNOT_CREATE_WRITER.get(
178          config.dn(), stackTraceToSingleLineString(e)));
179    }
180
181    return ccr;
182  }
183
184  private void configure(MultifileTextWriter mfWriter, FileBasedAccessLogPublisherCfg config) throws DirectoryException
185  {
186    final FilePermission perm = FilePermission.decodeUNIXMode(config.getLogFilePermissions());
187    final boolean writerAutoFlush = config.isAutoFlush() && !config.isAsynchronous();
188
189    final File logFile = getLogFile(config);
190    final FileNamingPolicy fnPolicy = new TimeStampNaming(logFile);
191
192    mfWriter.setNamingPolicy(fnPolicy);
193    mfWriter.setFilePermissions(perm);
194    mfWriter.setAppend(config.isAppend());
195    mfWriter.setAutoFlush(writerAutoFlush);
196    mfWriter.setBufferSize((int) config.getBufferSize());
197    mfWriter.setInterval(config.getTimeInterval());
198
199    mfWriter.removeAllRetentionPolicies();
200    mfWriter.removeAllRotationPolicies();
201    for (final DN dn : config.getRotationPolicyDNs())
202    {
203      mfWriter.addRotationPolicy(DirectoryServer.getRotationPolicy(dn));
204    }
205    for (final DN dn : config.getRetentionPolicyDNs())
206    {
207      mfWriter.addRetentionPolicy(DirectoryServer.getRetentionPolicy(dn));
208    }
209  }
210
211  private File getLogFile(final FileBasedAccessLogPublisherCfg config)
212  {
213    return getFileForPath(config.getLogFile());
214  }
215
216  @Override
217  public void initializeLogPublisher(final FileBasedAccessLogPublisherCfg cfg, ServerContext serverContext)
218      throws ConfigException, InitializationException
219  {
220    this.serverContext = serverContext;
221    final File logFile = getLogFile(cfg);
222    final FileNamingPolicy fnPolicy = new TimeStampNaming(logFile);
223
224    try
225    {
226      final FilePermission perm = FilePermission.decodeUNIXMode(cfg.getLogFilePermissions());
227      final LogPublisherErrorHandler errorHandler = new LogPublisherErrorHandler(cfg.dn());
228      final boolean writerAutoFlush = cfg.isAutoFlush() && !cfg.isAsynchronous();
229
230      final MultifileTextWriter theWriter = new MultifileTextWriter(
231          "Multifile Text Writer for " + cfg.dn(),
232          cfg.getTimeInterval(), fnPolicy, perm, errorHandler, "UTF-8",
233          writerAutoFlush, cfg.isAppend(), (int) cfg.getBufferSize());
234
235      // Validate retention and rotation policies.
236      for (final DN dn : cfg.getRotationPolicyDNs())
237      {
238        theWriter.addRotationPolicy(DirectoryServer.getRotationPolicy(dn));
239      }
240      for (final DN dn : cfg.getRetentionPolicyDNs())
241      {
242        theWriter.addRetentionPolicy(DirectoryServer.getRetentionPolicy(dn));
243      }
244
245      if (cfg.isAsynchronous())
246      {
247        this.writer = newAsyncWriter(theWriter, cfg);
248      }
249      else
250      {
251        this.writer = theWriter;
252      }
253    }
254    catch (final DirectoryException e)
255    {
256      throw new InitializationException(
257          ERR_CONFIG_LOGGING_CANNOT_CREATE_WRITER.get(cfg.dn(), e), e);
258    }
259    catch (final IOException e)
260    {
261      throw new InitializationException(
262          ERR_CONFIG_LOGGING_CANNOT_OPEN_FILE.get(logFile, cfg.dn(), e), e);
263    }
264
265    initializeFilters(cfg);
266
267    this.cfg = cfg;
268    isCombinedMode = cfg.getLogFormat() == LogFormat.COMBINED;
269    includeControlOIDs = cfg.isLogControlOids();
270    timeStampFormat = cfg.getLogRecordTimeFormat();
271
272    cfg.addFileBasedAccessChangeListener(this);
273  }
274
275  private boolean hasAsyncConfigChanged(FileBasedAccessLogPublisherCfg newConfig)
276  {
277    return hasParallelConfigChanged(newConfig) && cfg.getQueueSize() != newConfig.getQueueSize();
278  }
279
280  private boolean hasParallelConfigChanged(FileBasedAccessLogPublisherCfg newConfig)
281  {
282    return !cfg.dn().equals(newConfig.dn()) && cfg.isAutoFlush() != newConfig.isAutoFlush();
283  }
284
285  private AsynchronousTextWriter newAsyncWriter(MultifileTextWriter mfWriter, FileBasedAccessLogPublisherCfg config)
286  {
287    String name = "Asynchronous Text Writer for " + config.dn();
288    return new AsynchronousTextWriter(name, config.getQueueSize(), config.isAutoFlush(), mfWriter);
289  }
290
291  @Override
292  public boolean isConfigurationAcceptable(
293      final FileBasedAccessLogPublisherCfg configuration,
294      final List<LocalizableMessage> unacceptableReasons)
295  {
296    return isFilterConfigurationAcceptable(configuration, unacceptableReasons)
297        && isConfigurationChangeAcceptable(configuration, unacceptableReasons);
298  }
299
300  @Override
301  public boolean isConfigurationChangeAcceptable(
302      final FileBasedAccessLogPublisherCfg config,
303      final List<LocalizableMessage> unacceptableReasons)
304  {
305    // Validate the time-stamp formatter.
306    final String formatString = config.getLogRecordTimeFormat();
307    try
308    {
309       new SimpleDateFormat(formatString);
310    }
311    catch (final Exception e)
312    {
313      final LocalizableMessage message = ERR_CONFIG_LOGGING_INVALID_TIME_FORMAT.get(formatString);
314      unacceptableReasons.add(message);
315      return false;
316    }
317
318    // Make sure the permission is valid.
319    try
320    {
321      final FilePermission filePerm = FilePermission.decodeUNIXMode(config.getLogFilePermissions());
322      if (!filePerm.isOwnerWritable())
323      {
324        final LocalizableMessage message = ERR_CONFIG_LOGGING_INSANE_MODE.get(config.getLogFilePermissions());
325        unacceptableReasons.add(message);
326        return false;
327      }
328    }
329    catch (final DirectoryException e)
330    {
331      unacceptableReasons.add(ERR_CONFIG_LOGGING_MODE_INVALID.get(config.getLogFilePermissions(), e));
332      return false;
333    }
334
335    return true;
336  }
337
338  @Override
339  public void logAbandonRequest(final AbandonOperation abandonOperation)
340  {
341    if (isCombinedMode || !isRequestLoggable(abandonOperation))
342    {
343      return;
344    }
345
346    final StringBuilder buffer = new StringBuilder(100);
347    appendHeader(abandonOperation, "ABANDON", CATEGORY_REQUEST, buffer);
348    appendAbandonRequest(abandonOperation, buffer);
349    writer.writeRecord(buffer.toString());
350  }
351
352  @Override
353  public void logAbandonResult(final AbandonOperation abandonOperation)
354  {
355    if (!isResponseLoggable(abandonOperation))
356    {
357      return;
358    }
359
360    final StringBuilder buffer = new StringBuilder(100);
361    appendHeader(abandonOperation, "ABANDON", CATEGORY_RESPONSE, buffer);
362    if (isCombinedMode)
363    {
364      appendAbandonRequest(abandonOperation, buffer);
365    }
366    appendResultCodeAndMessage(buffer, abandonOperation);
367    logAdditionalLogItems(abandonOperation, buffer);
368    appendEtime(buffer, abandonOperation);
369    writer.writeRecord(buffer.toString());
370  }
371
372  @Override
373  public void logAddRequest(final AddOperation addOperation)
374  {
375    if (isCombinedMode || !isRequestLoggable(addOperation))
376    {
377      return;
378    }
379
380    final StringBuilder buffer = new StringBuilder(100);
381    appendHeader(addOperation, "ADD", CATEGORY_REQUEST, buffer);
382    appendAddRequest(addOperation, buffer);
383    writer.writeRecord(buffer.toString());
384  }
385
386  @Override
387  public void logAddResponse(final AddOperation addOperation)
388  {
389    if (!isResponseLoggable(addOperation))
390    {
391      return;
392    }
393
394    final StringBuilder buffer = new StringBuilder(100);
395    appendHeader(addOperation, "ADD", CATEGORY_RESPONSE, buffer);
396    if (isCombinedMode)
397    {
398      appendAddRequest(addOperation, buffer);
399    }
400    appendResultCodeAndMessage(buffer, addOperation);
401    logAdditionalLogItems(addOperation, buffer);
402    appendLabelIfNotNull(buffer, "authzDN", addOperation.getProxiedAuthorizationDN());
403    appendEtime(buffer, addOperation);
404    writer.writeRecord(buffer.toString());
405  }
406
407  @Override
408  public void logBindRequest(final BindOperation bindOperation)
409  {
410    if (isCombinedMode || !isRequestLoggable(bindOperation))
411    {
412      return;
413    }
414
415    final StringBuilder buffer = new StringBuilder(100);
416    appendHeader(bindOperation, "BIND", CATEGORY_REQUEST, buffer);
417    appendBindRequest(bindOperation, buffer);
418    writer.writeRecord(buffer.toString());
419  }
420
421  @Override
422  public void logBindResponse(final BindOperation bindOperation)
423  {
424    if (!isResponseLoggable(bindOperation))
425    {
426      return;
427    }
428
429    final StringBuilder buffer = new StringBuilder(100);
430    appendHeader(bindOperation, "BIND", CATEGORY_RESPONSE, buffer);
431    if (isCombinedMode)
432    {
433      appendBindRequest(bindOperation, buffer);
434    }
435    appendResultCodeAndMessage(buffer, bindOperation);
436
437    final LocalizableMessage failureMessage = bindOperation.getAuthFailureReason();
438    if (failureMessage != null)
439    {
440      // this code path is mutually exclusive with the if result code is success down below
441      appendLabel(buffer, "authFailureReason", failureMessage);
442      if (bindOperation.getSASLMechanism() != null
443          && bindOperation.getSASLAuthUserEntry() != null)
444      { // SASL bind and we have successfully found a user entry for auth
445        appendLabel(buffer, "authDN", bindOperation.getSASLAuthUserEntry().getName());
446      }
447      else
448      { // SASL bind failed to find user entry for auth or simple bind
449        appendLabel(buffer, "authDN", bindOperation.getRawBindDN());
450      }
451    }
452
453    logAdditionalLogItems(bindOperation, buffer);
454
455    if (bindOperation.getResultCode() == ResultCode.SUCCESS)
456    {
457      // this code path is mutually exclusive with the if failure message that exists just above
458      final AuthenticationInfo authInfo = bindOperation.getAuthenticationInfo();
459      if (authInfo != null)
460      {
461        final DN authDN = authInfo.getAuthenticationDN();
462        if (authDN != null)
463        {
464          appendLabel(buffer, "authDN", authDN);
465
466          final DN authzDN = authInfo.getAuthorizationDN();
467          if (!authDN.equals(authzDN))
468          {
469            appendLabel(buffer, "authzDN", authzDN);
470          }
471        }
472        else
473        {
474          buffer.append(" authDN=\"\"");
475        }
476      }
477    }
478
479    appendEtime(buffer, bindOperation);
480
481    writer.writeRecord(buffer.toString());
482  }
483
484  @Override
485  public void logCompareRequest(final CompareOperation compareOperation)
486  {
487    if (isCombinedMode || !isRequestLoggable(compareOperation))
488    {
489      return;
490    }
491
492    final StringBuilder buffer = new StringBuilder(100);
493    appendHeader(compareOperation, "COMPARE", CATEGORY_REQUEST, buffer);
494    appendCompareRequest(compareOperation, buffer);
495    writer.writeRecord(buffer.toString());
496  }
497
498  @Override
499  public void logCompareResponse(final CompareOperation compareOperation)
500  {
501    if (!isResponseLoggable(compareOperation))
502    {
503      return;
504    }
505
506    final StringBuilder buffer = new StringBuilder(100);
507    appendHeader(compareOperation, "COMPARE", CATEGORY_RESPONSE, buffer);
508    if (isCombinedMode)
509    {
510      appendCompareRequest(compareOperation, buffer);
511    }
512    appendResultCodeAndMessage(buffer, compareOperation);
513    logAdditionalLogItems(compareOperation, buffer);
514    appendLabelIfNotNull(buffer, "authzDN", compareOperation.getProxiedAuthorizationDN());
515    appendEtime(buffer, compareOperation);
516    writer.writeRecord(buffer.toString());
517  }
518
519  @Override
520  public void logConnect(final ClientConnection clientConnection)
521  {
522    if (!isConnectLoggable(clientConnection))
523    {
524      return;
525    }
526
527    final long connectionID = clientConnection.getConnectionID();
528    final StringBuilder buffer = new StringBuilder(100);
529    buffer.append('[').append(TimeThread.getUserDefinedTime(timeStampFormat)).append(']');
530    buffer.append(" CONNECT conn=").append(connectionID);
531    buffer.append(" from=").append(clientConnection.getClientHostPort());
532    buffer.append(" to=").append(clientConnection.getServerHostPort());
533    buffer.append(" protocol=").append(clientConnection.getProtocol());
534
535    writer.writeRecord(buffer.toString());
536  }
537
538  @Override
539  public void logDeleteRequest(final DeleteOperation deleteOperation)
540  {
541    if (isCombinedMode || !isRequestLoggable(deleteOperation))
542    {
543      return;
544    }
545
546    final StringBuilder buffer = new StringBuilder(100);
547    appendHeader(deleteOperation, "DELETE", CATEGORY_REQUEST, buffer);
548    appendDeleteRequest(deleteOperation, buffer);
549    writer.writeRecord(buffer.toString());
550  }
551
552  @Override
553  public void logDeleteResponse(final DeleteOperation deleteOperation)
554  {
555    if (!isResponseLoggable(deleteOperation))
556    {
557      return;
558    }
559
560    final StringBuilder buffer = new StringBuilder(100);
561    appendHeader(deleteOperation, "DELETE", CATEGORY_RESPONSE, buffer);
562    if (isCombinedMode)
563    {
564      appendDeleteRequest(deleteOperation, buffer);
565    }
566    appendResultCodeAndMessage(buffer, deleteOperation);
567    logAdditionalLogItems(deleteOperation, buffer);
568    appendLabelIfNotNull(buffer, "authzDN", deleteOperation.getProxiedAuthorizationDN());
569    appendEtime(buffer, deleteOperation);
570    writer.writeRecord(buffer.toString());
571  }
572
573  @Override
574  public void logDisconnect(final ClientConnection clientConnection,
575      final DisconnectReason disconnectReason, final LocalizableMessage message)
576  {
577    if (!isDisconnectLoggable(clientConnection))
578    {
579      return;
580    }
581
582    final long connectionID = clientConnection.getConnectionID();
583    final StringBuilder buffer = new StringBuilder(100);
584    buffer.append('[').append(TimeThread.getUserDefinedTime(timeStampFormat)).append(']');
585    buffer.append(" DISCONNECT conn=").append(connectionID);
586    appendLabel(buffer, "reason", disconnectReason);
587    appendLabelIfNotNull(buffer, "msg", message);
588
589    writer.writeRecord(buffer.toString());
590  }
591
592  @Override
593  public void logExtendedRequest(final ExtendedOperation extendedOperation)
594  {
595    if (isCombinedMode || !isRequestLoggable(extendedOperation))
596    {
597      return;
598    }
599
600    final StringBuilder buffer = new StringBuilder(100);
601    appendHeader(extendedOperation, "EXTENDED", CATEGORY_REQUEST, buffer);
602    appendExtendedRequest(extendedOperation, buffer);
603    writer.writeRecord(buffer.toString());
604  }
605
606  @Override
607  public void logExtendedResponse(final ExtendedOperation extendedOperation)
608  {
609    if (!isResponseLoggable(extendedOperation))
610    {
611      return;
612    }
613
614    final StringBuilder buffer = new StringBuilder(100);
615    appendHeader(extendedOperation, "EXTENDED", CATEGORY_RESPONSE, buffer);
616    if (isCombinedMode)
617    {
618      appendExtendedRequest(extendedOperation, buffer);
619    }
620
621    final String oid = extendedOperation.getResponseOID();
622    if (oid != null)
623    {
624      final ExtendedOperationHandler<?> extOpHandler = DirectoryServer
625          .getExtendedOperationHandler(oid);
626      if (extOpHandler != null)
627      {
628        String name = extOpHandler.getExtendedOperationName();
629        appendLabelIfNotNull(buffer, "name", name);
630      }
631      appendLabel(buffer, "oid", oid);
632    }
633    appendResultCodeAndMessage(buffer, extendedOperation);
634    logAdditionalLogItems(extendedOperation, buffer);
635    appendEtime(buffer, extendedOperation);
636
637    writer.writeRecord(buffer.toString());
638  }
639
640  @Override
641  public void logModifyDNRequest(final ModifyDNOperation modifyDNOperation)
642  {
643    if (isCombinedMode || !isRequestLoggable(modifyDNOperation))
644    {
645      return;
646    }
647
648    final StringBuilder buffer = new StringBuilder(100);
649    appendHeader(modifyDNOperation, "MODIFYDN", CATEGORY_REQUEST, buffer);
650    appendModifyDNRequest(modifyDNOperation, buffer);
651    writer.writeRecord(buffer.toString());
652  }
653
654  @Override
655  public void logModifyDNResponse(final ModifyDNOperation modifyDNOperation)
656  {
657    if (!isResponseLoggable(modifyDNOperation))
658    {
659      return;
660    }
661
662    final StringBuilder buffer = new StringBuilder(100);
663    appendHeader(modifyDNOperation, "MODIFYDN", CATEGORY_RESPONSE, buffer);
664    if (isCombinedMode)
665    {
666      appendModifyDNRequest(modifyDNOperation, buffer);
667    }
668    appendResultCodeAndMessage(buffer, modifyDNOperation);
669    logAdditionalLogItems(modifyDNOperation, buffer);
670    appendLabelIfNotNull(buffer, "authzDN", modifyDNOperation.getProxiedAuthorizationDN());
671    appendEtime(buffer, modifyDNOperation);
672    writer.writeRecord(buffer.toString());
673  }
674
675  @Override
676  public void logModifyRequest(final ModifyOperation modifyOperation)
677  {
678    if (isCombinedMode || !isRequestLoggable(modifyOperation))
679    {
680      return;
681    }
682
683    final StringBuilder buffer = new StringBuilder(100);
684    appendHeader(modifyOperation, "MODIFY", CATEGORY_REQUEST, buffer);
685    appendModifyRequest(modifyOperation, buffer);
686    writer.writeRecord(buffer.toString());
687  }
688
689  @Override
690  public void logModifyResponse(final ModifyOperation modifyOperation)
691  {
692    if (!isResponseLoggable(modifyOperation))
693    {
694      return;
695    }
696
697    final StringBuilder buffer = new StringBuilder(100);
698    appendHeader(modifyOperation, "MODIFY", CATEGORY_RESPONSE, buffer);
699    if (isCombinedMode)
700    {
701      appendModifyRequest(modifyOperation, buffer);
702    }
703    appendResultCodeAndMessage(buffer, modifyOperation);
704    logAdditionalLogItems(modifyOperation, buffer);
705    appendLabelIfNotNull(buffer, "authzDN", modifyOperation.getProxiedAuthorizationDN());
706    appendEtime(buffer, modifyOperation);
707    writer.writeRecord(buffer.toString());
708  }
709
710  @Override
711  public void logSearchRequest(final SearchOperation searchOperation)
712  {
713    if (isCombinedMode || !isRequestLoggable(searchOperation))
714    {
715      return;
716    }
717
718    final StringBuilder buffer = new StringBuilder(192);
719    appendHeader(searchOperation, "SEARCH", CATEGORY_REQUEST, buffer);
720    appendSearchRequest(searchOperation, buffer);
721    writer.writeRecord(buffer.toString());
722  }
723
724  @Override
725  public void logSearchResultDone(final SearchOperation searchOperation)
726  {
727    if (!isResponseLoggable(searchOperation))
728    {
729      return;
730    }
731
732    final StringBuilder buffer = new StringBuilder(128);
733    appendHeader(searchOperation, "SEARCH", CATEGORY_RESPONSE, buffer);
734    if (isCombinedMode)
735    {
736      appendSearchRequest(searchOperation, buffer);
737    }
738    appendResultCodeAndMessage(buffer, searchOperation);
739    buffer.append(" nentries=").append(searchOperation.getEntriesSent());
740    logAdditionalLogItems(searchOperation, buffer);
741    appendLabelIfNotNull(buffer, "authzDN", searchOperation.getProxiedAuthorizationDN());
742    appendEtime(buffer, searchOperation);
743    writer.writeRecord(buffer.toString());
744  }
745
746  @Override
747  public void logUnbind(final UnbindOperation unbindOperation)
748  {
749    if (!isRequestLoggable(unbindOperation))
750    {
751      return;
752    }
753
754    final StringBuilder buffer = new StringBuilder(100);
755    appendHeader(unbindOperation, "UNBIND", CATEGORY_REQUEST, buffer);
756    if (unbindOperation.isSynchronizationOperation())
757    {
758      buffer.append(" type=synchronization");
759    }
760
761    writer.writeRecord(buffer.toString());
762  }
763
764  @Override
765  protected void close0()
766  {
767    writer.shutdown();
768    TimeThread.removeUserDefinedFormatter(timeStampFormat);
769    if (cfg != null)
770    {
771      cfg.removeFileBasedAccessChangeListener(this);
772    }
773  }
774
775  private void appendAbandonRequest(final AbandonOperation abandonOperation, final StringBuilder buffer)
776  {
777    buffer.append(" idToAbandon=");
778    buffer.append(abandonOperation.getIDToAbandon());
779    appendRequestControls(abandonOperation, buffer);
780    if (abandonOperation.isSynchronizationOperation())
781    {
782      buffer.append(" type=synchronization");
783    }
784  }
785
786  private void appendAddRequest(final AddOperation addOperation, final StringBuilder buffer)
787  {
788    appendLabel(buffer, "dn", addOperation.getRawEntryDN());
789    appendRequestControls(addOperation, buffer);
790    if (addOperation.isSynchronizationOperation())
791    {
792      buffer.append(" type=synchronization");
793    }
794  }
795
796  private void appendBindRequest(final BindOperation bindOperation, final StringBuilder buffer)
797  {
798    final String protocolVersion = bindOperation.getProtocolVersion();
799    if (protocolVersion != null)
800    {
801      buffer.append(" version=");
802      buffer.append(protocolVersion);
803    }
804
805    switch (bindOperation.getAuthenticationType())
806    {
807    case SIMPLE:
808      buffer.append(" type=SIMPLE");
809      break;
810    case SASL:
811      buffer.append(" type=SASL mechanism=").append(bindOperation.getSASLMechanism());
812      break;
813    default:
814      buffer.append(" type=").append(bindOperation.getAuthenticationType());
815      break;
816    }
817
818    appendLabel(buffer, "dn", bindOperation.getRawBindDN());
819    appendRequestControls(bindOperation, buffer);
820    if (bindOperation.isSynchronizationOperation())
821    {
822      buffer.append(" type=synchronization");
823    }
824  }
825
826  private void appendCompareRequest(final CompareOperation compareOperation, final StringBuilder buffer)
827  {
828    appendLabel(buffer, "dn", compareOperation.getRawEntryDN());
829    buffer.append(" attr=");
830    buffer.append(compareOperation.getAttributeDescription().getAttributeType().getNameOrOID());
831    appendRequestControls(compareOperation, buffer);
832    if (compareOperation.isSynchronizationOperation())
833    {
834      buffer.append(" type=synchronization");
835    }
836  }
837
838  private void appendDeleteRequest(final DeleteOperation deleteOperation, final StringBuilder buffer)
839  {
840    appendLabel(buffer, "dn", deleteOperation.getRawEntryDN());
841    appendRequestControls(deleteOperation, buffer);
842    if (deleteOperation.isSynchronizationOperation())
843    {
844      buffer.append(" type=synchronization");
845    }
846  }
847
848  private void appendExtendedRequest(final ExtendedOperation extendedOperation,
849      final StringBuilder buffer)
850  {
851    final String oid = extendedOperation.getRequestOID();
852    final ExtendedOperationHandler<?> extOpHandler = DirectoryServer.getExtendedOperationHandler(oid);
853    if (extOpHandler != null)
854    {
855      final String name = extOpHandler.getExtendedOperationName();
856      appendLabelIfNotNull(buffer, "name", name);
857    }
858    appendLabel(buffer, "oid", oid);
859    appendRequestControls(extendedOperation, buffer);
860    if (extendedOperation.isSynchronizationOperation())
861    {
862      buffer.append(" type=synchronization");
863    }
864  }
865
866  private void appendLabel(final StringBuilder buffer, final String label, final Object obj)
867  {
868    buffer.append(' ').append(label).append("=\"");
869    if (obj != null)
870    {
871      buffer.append(obj);
872    }
873    buffer.append('\"');
874  }
875
876  private void appendLabelIfNotNull(final StringBuilder buffer, final String label, final Object obj)
877  {
878    if (obj != null)
879    {
880      appendLabel(buffer, label, obj);
881    }
882  }
883
884  private void appendResultCodeAndMessage(StringBuilder buffer, Operation operation)
885  {
886    buffer.append(" result=");
887    buffer.append(operation.getResultCode().intValue());
888
889    final LocalizableMessageBuilder msg = operation.getErrorMessage();
890    if (msg != null && msg.length() > 0)
891    {
892      appendLabel(buffer, "message", msg);
893    }
894
895    if (operation.getMaskedResultCode() != null)
896    {
897      buffer.append(" maskedResult=");
898      buffer.append(operation.getMaskedResultCode().intValue());
899    }
900    final LocalizableMessageBuilder maskedMsg = operation.getMaskedErrorMessage();
901    if (maskedMsg != null && maskedMsg.length() > 0)
902    {
903      appendLabel(buffer, "maskedMessage", maskedMsg);
904    }
905  }
906
907  private void appendEtime(final StringBuilder buffer, final Operation operation)
908  {
909    buffer.append(" etime=");
910    // the server can be configured to log processing time as nanos xor millis
911    long etime = operation.getProcessingNanoTime();
912    if (etime <= -1)
913    {
914      // if it is not configured for nanos, then use millis.
915      etime = operation.getProcessingTime();
916    }
917    buffer.append(etime);
918  }
919
920  /** Appends the common log header information to the provided buffer. */
921  private void appendHeader(final Operation operation, final String opType,
922      final String category, final StringBuilder buffer)
923  {
924    buffer.append('[').append(TimeThread.getUserDefinedTime(timeStampFormat)).append("] ");
925    buffer.append(opType);
926    if (!isCombinedMode)
927    {
928      buffer.append(' ').append(category);
929    }
930    buffer.append(" conn=").append(operation.getConnectionID());
931    buffer.append(" op=").append(operation.getOperationID());
932    buffer.append(" msgID=").append(operation.getMessageID());
933    appendTransactionId(operation, buffer);
934  }
935
936  private void appendModifyDNRequest(final ModifyDNOperation modifyDNOperation,
937      final StringBuilder buffer)
938  {
939    appendLabel(buffer, "dn", modifyDNOperation.getRawEntryDN());
940    appendLabel(buffer, "newRDN", modifyDNOperation.getRawNewRDN());
941    appendLabel(buffer, "deleteOldRDN", modifyDNOperation.deleteOldRDN());
942
943    final ByteString newSuperior = modifyDNOperation.getRawNewSuperior();
944    appendLabelIfNotNull(buffer, "newSuperior", newSuperior);
945    appendRequestControls(modifyDNOperation, buffer);
946    if (modifyDNOperation.isSynchronizationOperation())
947    {
948      buffer.append(" type=synchronization");
949    }
950  }
951
952  private void appendModifyRequest(final ModifyOperation modifyOperation, final StringBuilder buffer)
953  {
954    appendLabel(buffer, "dn", modifyOperation.getRawEntryDN());
955    appendRequestControls(modifyOperation, buffer);
956    if (modifyOperation.isSynchronizationOperation())
957    {
958      buffer.append(" type=synchronization");
959    }
960  }
961
962  private void appendTransactionId(Operation operation, final StringBuilder buffer)
963  {
964    // In test context, serverContext may be null
965    if (serverContext != null && serverContext.getCommonAudit().shouldTrustTransactionIds())
966    {
967      String transactionId = getTransactionIdFromControl(operation);
968      if (transactionId != null)
969      {
970        buffer.append(" transactionId=").append(transactionId);
971      }
972    }
973  }
974
975  private String getTransactionIdFromControl(Operation operation)
976  {
977    try
978    {
979      TransactionIdControl control = operation.getRequestControl(TransactionIdControl.DECODER);
980      return control != null ? control.getTransactionId() : null;
981    }
982    catch (DirectoryException e)
983    {
984      logger.error(ERR_COMMON_AUDIT_INVALID_TRANSACTION_ID.get(StaticUtils.stackTraceToSingleLineString(e)));
985    }
986    return null;
987  }
988
989  private void appendRequestControls(final Operation operation, final StringBuilder buffer)
990  {
991    appendControls(buffer, " requestControls=", operation.getRequestControls());
992  }
993
994  private void appendResponseControls(final Operation operation, final StringBuilder buffer)
995  {
996    appendControls(buffer, " responseControls=", operation.getResponseControls());
997  }
998
999  private void appendControls(final StringBuilder buffer, String label, List<Control> controls)
1000  {
1001    if (includeControlOIDs && !controls.isEmpty())
1002    {
1003      buffer.append(label);
1004      boolean isFirst = true;
1005      for (final Control control : controls)
1006      {
1007        if (!isFirst)
1008        {
1009          buffer.append(",");
1010        }
1011        buffer.append(control.getOID());
1012        isFirst = false;
1013      }
1014    }
1015  }
1016
1017  private void appendSearchRequest(final SearchOperation searchOperation, final StringBuilder buffer)
1018  {
1019    appendLabel(buffer, "base", searchOperation.getRawBaseDN());
1020    buffer.append(" scope=");
1021    buffer.append(searchOperation.getScope());
1022    buffer.append(" filter=\"");
1023    searchOperation.getRawFilter().toString(buffer);
1024
1025    final Set<String> attrs = searchOperation.getAttributes();
1026    if (attrs == null || attrs.isEmpty())
1027    {
1028      buffer.append("\" attrs=\"ALL\"");
1029    }
1030    else
1031    {
1032      buffer.append("\" attrs=\"");
1033      Utils.joinAsString(buffer, ",", attrs);
1034      buffer.append("\"");
1035    }
1036    appendRequestControls(searchOperation, buffer);
1037    if (searchOperation.isSynchronizationOperation())
1038    {
1039      buffer.append(" type=synchronization");
1040    }
1041  }
1042
1043  /** Appends additional log items to the provided builder. */
1044  private void logAdditionalLogItems(final Operation operation, final StringBuilder builder)
1045  {
1046    appendResponseControls(operation, builder);
1047    for (final AdditionalLogItem item : operation.getAdditionalLogItems())
1048    {
1049      builder.append(' ');
1050      item.toString(builder);
1051    }
1052  }
1053}