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