View Javadoc
1   /*
2    * Licensed to the Apache Software Foundation (ASF) under one
3    * or more contributor license agreements.  See the NOTICE file
4    * distributed with this work for additional information
5    * regarding copyright ownership.  The ASF licenses this file
6    * to you under the Apache License, Version 2.0 (the
7    * "License"); you may not use this file except in compliance
8    * with the License.  You may obtain a copy of the License at
9    *
10   *   http://www.apache.org/licenses/LICENSE-2.0
11   *
12   * Unless required by applicable law or agreed to in writing,
13   * software distributed under the License is distributed on an
14   * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
15   * KIND, either express or implied.  See the License for the
16   * specific language governing permissions and limitations
17   * under the License.
18   */
19  package org.apache.maven.cli.event;
20  
21  import java.io.File;
22  import java.nio.file.Path;
23  import java.util.List;
24  import java.util.Objects;
25  
26  import org.apache.maven.api.services.MessageBuilder;
27  import org.apache.maven.api.services.MessageBuilderFactory;
28  import org.apache.maven.execution.AbstractExecutionListener;
29  import org.apache.maven.execution.BuildFailure;
30  import org.apache.maven.execution.BuildSuccess;
31  import org.apache.maven.execution.BuildSummary;
32  import org.apache.maven.execution.ExecutionEvent;
33  import org.apache.maven.execution.MavenExecutionResult;
34  import org.apache.maven.execution.MavenSession;
35  import org.apache.maven.logwrapper.LogLevelRecorder;
36  import org.apache.maven.logwrapper.MavenSlf4jWrapperFactory;
37  import org.apache.maven.plugin.MojoExecution;
38  import org.apache.maven.plugin.descriptor.MojoDescriptor;
39  import org.apache.maven.project.MavenProject;
40  import org.slf4j.ILoggerFactory;
41  import org.slf4j.Logger;
42  import org.slf4j.LoggerFactory;
43  
44  import static org.apache.maven.cli.CLIReportingUtils.formatDuration;
45  import static org.apache.maven.cli.CLIReportingUtils.formatTimestamp;
46  
47  /**
48   * Logs execution events to logger, eventually user-supplied.
49   *
50   */
51  public class ExecutionEventLogger extends AbstractExecutionListener {
52      private static final int MAX_LOG_PREFIX_SIZE = 8; // "[ERROR] "
53      private static final int PROJECT_STATUS_SUFFIX_SIZE = 20; // "SUCCESS [  0.000 s]"
54      private static final int MIN_TERMINAL_WIDTH = 60;
55      private static final int DEFAULT_TERMINAL_WIDTH = 80;
56      private static final int MAX_TERMINAL_WIDTH = 130;
57      private static final int MAX_PADDED_BUILD_TIME_DURATION_LENGTH = 9;
58  
59      private final MessageBuilderFactory messageBuilderFactory;
60      private final Logger logger;
61      private int terminalWidth;
62      private int lineLength;
63      private int maxProjectNameLength;
64      private int totalProjects;
65      private volatile int currentVisitedProjectCount;
66  
67      public ExecutionEventLogger(MessageBuilderFactory messageBuilderFactory) {
68          this(messageBuilderFactory, LoggerFactory.getLogger(ExecutionEventLogger.class));
69      }
70  
71      public ExecutionEventLogger(MessageBuilderFactory messageBuilderFactory, Logger logger) {
72          this(messageBuilderFactory, logger, -1);
73      }
74  
75      public ExecutionEventLogger(MessageBuilderFactory messageBuilderFactory, Logger logger, int terminalWidth) {
76          this.logger = Objects.requireNonNull(logger, "logger cannot be null");
77          this.messageBuilderFactory = messageBuilderFactory;
78          this.terminalWidth = terminalWidth;
79      }
80  
81      private static String chars(char c, int count) {
82          StringBuilder buffer = new StringBuilder(count);
83  
84          for (int i = count; i > 0; i--) {
85              buffer.append(c);
86          }
87  
88          return buffer.toString();
89      }
90  
91      private void infoLine(char c) {
92          infoMain(chars(c, lineLength));
93      }
94  
95      private void infoMain(String msg) {
96          logger.info(builder().strong(msg).toString());
97      }
98  
99      private void init() {
100         if (maxProjectNameLength == 0) {
101             if (terminalWidth < 0) {
102                 terminalWidth = messageBuilderFactory.getTerminalWidth();
103             }
104             terminalWidth = Math.min(
105                     MAX_TERMINAL_WIDTH,
106                     Math.max(terminalWidth < 0 ? DEFAULT_TERMINAL_WIDTH : terminalWidth, MIN_TERMINAL_WIDTH));
107             lineLength = terminalWidth - MAX_LOG_PREFIX_SIZE;
108             maxProjectNameLength = lineLength - PROJECT_STATUS_SUFFIX_SIZE;
109         }
110     }
111 
112     @Override
113     public void projectDiscoveryStarted(ExecutionEvent event) {
114         if (logger.isInfoEnabled()) {
115             init();
116             logger.info("Scanning for projects...");
117         }
118     }
119 
120     @Override
121     public void sessionStarted(ExecutionEvent event) {
122         if (logger.isInfoEnabled() && event.getSession().getProjects().size() > 1) {
123             init();
124             infoLine('-');
125 
126             infoMain("Reactor Build Order:");
127 
128             logger.info("");
129 
130             final List<MavenProject> projects = event.getSession().getProjects();
131             for (MavenProject project : projects) {
132                 int len = lineLength
133                         - project.getName().length()
134                         - project.getPackaging().length()
135                         - 2;
136                 logger.info("{}{}[{}]", project.getName(), chars(' ', (len > 0) ? len : 1), project.getPackaging());
137             }
138 
139             final List<MavenProject> allProjects = event.getSession().getAllProjects();
140             final int projectsSkipped = allProjects.size() - projects.size();
141 
142             currentVisitedProjectCount = projectsSkipped;
143             totalProjects = allProjects.size();
144         }
145     }
146 
147     @Override
148     public void sessionEnded(ExecutionEvent event) {
149         if (logger.isInfoEnabled()) {
150             init();
151             if (event.getSession().getProjects().size() > 1) {
152                 logReactorSummary(event.getSession());
153             }
154 
155             ILoggerFactory iLoggerFactory = LoggerFactory.getILoggerFactory();
156 
157             if (iLoggerFactory instanceof MavenSlf4jWrapperFactory) {
158                 MavenSlf4jWrapperFactory loggerFactory = (MavenSlf4jWrapperFactory) iLoggerFactory;
159                 loggerFactory
160                         .getLogLevelRecorder()
161                         .filter(LogLevelRecorder::metThreshold)
162                         .ifPresent(recorder -> event.getSession()
163                                 .getResult()
164                                 .addException(new Exception(
165                                         "Build failed due to log statements with a higher severity than allowed. "
166                                                 + "Fix the logged issues or remove flag --fail-on-severity (-fos).")));
167             }
168 
169             logResult(event.getSession());
170 
171             logStats(event.getSession());
172 
173             infoLine('-');
174         }
175     }
176 
177     private boolean isSingleVersionedReactor(MavenSession session) {
178         boolean result = true;
179 
180         MavenProject topProject = session.getTopLevelProject();
181         List<MavenProject> sortedProjects = session.getProjectDependencyGraph().getSortedProjects();
182         for (MavenProject mavenProject : sortedProjects) {
183             if (!topProject.getVersion().equals(mavenProject.getVersion())) {
184                 result = false;
185                 break;
186             }
187         }
188 
189         return result;
190     }
191 
192     private void logReactorSummary(MavenSession session) {
193         boolean isSingleVersion = isSingleVersionedReactor(session);
194 
195         infoLine('-');
196 
197         StringBuilder summary = new StringBuilder("Reactor Summary");
198         if (isSingleVersion) {
199             summary.append(" for ");
200             summary.append(session.getTopLevelProject().getName());
201             summary.append(" ");
202             summary.append(session.getTopLevelProject().getVersion());
203         }
204         summary.append(":");
205         infoMain(summary.toString());
206 
207         logger.info("");
208 
209         MavenExecutionResult result = session.getResult();
210 
211         List<MavenProject> projects = session.getProjects();
212 
213         StringBuilder buffer = new StringBuilder(128);
214 
215         for (MavenProject project : projects) {
216             buffer.append(project.getName());
217             buffer.append(' ');
218 
219             if (!isSingleVersion) {
220                 buffer.append(project.getVersion());
221                 buffer.append(' ');
222             }
223 
224             if (buffer.length() <= maxProjectNameLength) {
225                 while (buffer.length() < maxProjectNameLength) {
226                     buffer.append('.');
227                 }
228                 buffer.append(' ');
229             }
230 
231             BuildSummary buildSummary = result.getBuildSummary(project);
232 
233             if (buildSummary == null) {
234                 buffer.append(builder().warning("SKIPPED"));
235             } else if (buildSummary instanceof BuildSuccess) {
236                 buffer.append(builder().success("SUCCESS"));
237                 buffer.append(" [");
238                 String buildTimeDuration = formatDuration(buildSummary.getTime());
239                 int padSize = MAX_PADDED_BUILD_TIME_DURATION_LENGTH - buildTimeDuration.length();
240                 if (padSize > 0) {
241                     buffer.append(chars(' ', padSize));
242                 }
243                 buffer.append(buildTimeDuration);
244                 buffer.append(']');
245             } else if (buildSummary instanceof BuildFailure) {
246                 buffer.append(builder().failure("FAILURE"));
247                 buffer.append(" [");
248                 String buildTimeDuration = formatDuration(buildSummary.getTime());
249                 int padSize = MAX_PADDED_BUILD_TIME_DURATION_LENGTH - buildTimeDuration.length();
250                 if (padSize > 0) {
251                     buffer.append(chars(' ', padSize));
252                 }
253                 buffer.append(buildTimeDuration);
254                 buffer.append(']');
255             }
256 
257             logger.info(buffer.toString());
258             buffer.setLength(0);
259         }
260     }
261 
262     private void logResult(MavenSession session) {
263         infoLine('-');
264         MessageBuilder buffer = builder();
265 
266         if (session.getResult().hasExceptions()) {
267             buffer.failure("BUILD FAILURE");
268         } else {
269             buffer.success("BUILD SUCCESS");
270         }
271         logger.info(buffer.toString());
272     }
273 
274     private MessageBuilder builder() {
275         return messageBuilderFactory.builder();
276     }
277 
278     private void logStats(MavenSession session) {
279         infoLine('-');
280 
281         long finish = System.currentTimeMillis();
282 
283         long time = finish - session.getRequest().getStartTime().getTime();
284 
285         String wallClock = session.getRequest().getDegreeOfConcurrency() > 1 ? " (Wall Clock)" : "";
286 
287         logger.info("Total time:  {}{}", formatDuration(time), wallClock);
288 
289         logger.info("Finished at: {}", formatTimestamp(finish));
290     }
291 
292     @Override
293     public void projectSkipped(ExecutionEvent event) {
294         if (logger.isInfoEnabled()) {
295             init();
296             logger.info("");
297             infoLine('-');
298             String name = event.getProject().getName();
299             infoMain("Skipping " + name);
300             logger.info(name + " was not built because a module it depends on failed to build.");
301 
302             infoLine('-');
303         }
304     }
305 
306     @Override
307     public void projectStarted(ExecutionEvent event) {
308         if (logger.isInfoEnabled()) {
309             init();
310             MavenProject project = event.getProject();
311 
312             logger.info("");
313 
314             // -------< groupId:artifactId >-------
315             String projectKey = project.getGroupId() + ':' + project.getArtifactId();
316 
317             final String preHeader = "--< ";
318             final String postHeader = " >--";
319 
320             final int headerLen = preHeader.length() + projectKey.length() + postHeader.length();
321 
322             String prefix = chars('-', Math.max(0, (lineLength - headerLen) / 2)) + preHeader;
323 
324             String suffix =
325                     postHeader + chars('-', Math.max(0, lineLength - headerLen - prefix.length() + preHeader.length()));
326 
327             logger.info(
328                     builder().strong(prefix).project(projectKey).strong(suffix).toString());
329 
330             // Building Project Name Version    [i/n]
331             String building = "Building " + event.getProject().getName() + " "
332                     + event.getProject().getVersion();
333 
334             if (totalProjects <= 1) {
335                 infoMain(building);
336             } else {
337                 // display progress [i/n]
338                 int number;
339                 synchronized (this) {
340                     number = ++currentVisitedProjectCount;
341                 }
342                 String progress = " [" + number + '/' + totalProjects + ']';
343 
344                 int pad = lineLength - building.length() - progress.length();
345 
346                 infoMain(building + ((pad > 0) ? chars(' ', pad) : "") + progress);
347             }
348 
349             // path to pom.xml
350             File currentPom = project.getFile();
351             if (currentPom != null) {
352                 MavenSession session = event.getSession();
353                 Path current = currentPom.toPath().toAbsolutePath().normalize();
354                 Path topDirectory = session.getTopDirectory();
355                 if (topDirectory != null && current.startsWith(topDirectory)) {
356                     current = topDirectory.relativize(current);
357                 }
358                 logger.info("  from " + current);
359             }
360 
361             // ----------[ packaging ]----------
362             prefix = chars('-', Math.max(0, (lineLength - project.getPackaging().length() - 4) / 2));
363             suffix = chars('-', Math.max(0, lineLength - project.getPackaging().length() - 4 - prefix.length()));
364             infoMain(prefix + "[ " + project.getPackaging() + " ]" + suffix);
365         }
366     }
367 
368     @Override
369     public void mojoSkipped(ExecutionEvent event) {
370         if (logger.isWarnEnabled()) {
371             init();
372             logger.warn(
373                     "Goal '{}' requires online mode for execution but Maven is currently offline, skipping",
374                     event.getMojoExecution().getGoal());
375         }
376     }
377 
378     /**
379      * <pre>--- mojo-artifactId:version:goal (mojo-executionId) @ project-artifactId ---</pre>
380      */
381     @Override
382     public void mojoStarted(ExecutionEvent event) {
383         if (logger.isInfoEnabled()) {
384             init();
385             logger.info("");
386 
387             MessageBuilder buffer = builder().strong("--- ");
388             append(buffer, event.getMojoExecution());
389             append(buffer, event.getProject());
390             buffer.strong(" ---");
391 
392             logger.info(buffer.toString());
393         }
394     }
395 
396     // CHECKSTYLE_OFF: LineLength
397     /**
398      * <pre>&gt;&gt;&gt; mojo-artifactId:version:goal (mojo-executionId) &gt; :forked-goal @ project-artifactId &gt;&gt;&gt;</pre>
399      * <pre>&gt;&gt;&gt; mojo-artifactId:version:goal (mojo-executionId) &gt; [lifecycle]phase @ project-artifactId &gt;&gt;&gt;</pre>
400      */
401     // CHECKSTYLE_ON: LineLength
402     @Override
403     public void forkStarted(ExecutionEvent event) {
404         if (logger.isInfoEnabled()) {
405             init();
406             logger.info("");
407 
408             MessageBuilder buffer = builder().strong(">>> ");
409             append(buffer, event.getMojoExecution());
410             buffer.strong(" > ");
411             appendForkInfo(buffer, event.getMojoExecution().getMojoDescriptor());
412             append(buffer, event.getProject());
413             buffer.strong(" >>>");
414 
415             logger.info(buffer.toString());
416         }
417     }
418 
419     // CHECKSTYLE_OFF: LineLength
420     /**
421      * <pre>&lt;&lt;&lt; mojo-artifactId:version:goal (mojo-executionId) &lt; :forked-goal @ project-artifactId &lt;&lt;&lt;</pre>
422      * <pre>&lt;&lt;&lt; mojo-artifactId:version:goal (mojo-executionId) &lt; [lifecycle]phase @ project-artifactId &lt;&lt;&lt;</pre>
423      */
424     // CHECKSTYLE_ON: LineLength
425     @Override
426     public void forkSucceeded(ExecutionEvent event) {
427         if (logger.isInfoEnabled()) {
428             init();
429             logger.info("");
430 
431             MessageBuilder buffer = builder().strong("<<< ");
432             append(buffer, event.getMojoExecution());
433             buffer.strong(" < ");
434             appendForkInfo(buffer, event.getMojoExecution().getMojoDescriptor());
435             append(buffer, event.getProject());
436             buffer.strong(" <<<");
437 
438             logger.info(buffer.toString());
439 
440             logger.info("");
441         }
442     }
443 
444     private void append(MessageBuilder buffer, MojoExecution me) {
445         String prefix = me.getMojoDescriptor().getPluginDescriptor().getGoalPrefix();
446         if (prefix == null || prefix.isEmpty()) {
447             prefix = me.getGroupId() + ":" + me.getArtifactId();
448         }
449         buffer.mojo(prefix + ':' + me.getVersion() + ':' + me.getGoal());
450         if (me.getExecutionId() != null) {
451             buffer.a(' ').strong('(' + me.getExecutionId() + ')');
452         }
453     }
454 
455     private void appendForkInfo(MessageBuilder buffer, MojoDescriptor md) {
456         StringBuilder buff = new StringBuilder();
457         if (md.getExecutePhase() != null && !md.getExecutePhase().isEmpty()) {
458             // forked phase
459             if (md.getExecuteLifecycle() != null && !md.getExecuteLifecycle().isEmpty()) {
460                 buff.append('[');
461                 buff.append(md.getExecuteLifecycle());
462                 buff.append(']');
463             }
464             buff.append(md.getExecutePhase());
465         } else {
466             // forked goal
467             buff.append(':');
468             buff.append(md.getExecuteGoal());
469         }
470         buffer.strong(buff.toString());
471     }
472 
473     private void append(MessageBuilder buffer, MavenProject project) {
474         buffer.a(" @ ").project(project.getArtifactId());
475     }
476 
477     @Override
478     public void forkedProjectStarted(ExecutionEvent event) {
479         if (logger.isInfoEnabled()
480                 && event.getMojoExecution().getForkedExecutions().size() > 1) {
481             init();
482             logger.info("");
483             infoLine('>');
484 
485             infoMain("Forking " + event.getProject().getName() + " "
486                     + event.getProject().getVersion());
487 
488             infoLine('>');
489         }
490     }
491 }