View Javadoc

1   /*
2    * Copyright 2007 united internet (unitedinternet.com) Robert Zimmermann
3    *
4    *  Licensed under the Apache License, Version 2.0 (the "License");
5    *  you may not use this file except in compliance with the License.
6    *  You may obtain a copy of the License at
7    *
8    *      http://www.apache.org/licenses/LICENSE-2.0
9    *
10   *  Unless required by applicable law or agreed to in writing, software
11   *  distributed under the License is distributed on an "AS IS" BASIS,
12   *  WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13   *  See the License for the specific language governing permissions and
14   *  limitations under the License.
15   *
16   */
17  package com.unitedinternet.portal.selenium.utils.logging;
18  
19  import java.util.ArrayList;
20  import java.util.Arrays;
21  import java.util.List;
22  
23  import org.apache.commons.lang.ArrayUtils;
24  
25  import com.thoughtworks.selenium.CommandProcessor;
26  import com.thoughtworks.selenium.HttpCommandProcessor;
27  
28  /**
29   * Logs processed selenium commands (processed via remote-control) with an arbitrary LoggingResultsFormatter. The formatter is
30   * responsible for writing logging events. A List of Selenium-Commands can be excluded from logging. Default is "getHtmlSource".
31   * Calls to selenium from within com.thoughtworks.selenium.Wait will be filtered and logged only once. Wait should not be the last
32   * command in execution (except in error, eg. timeout situation), as there is no way up to now to know that the last Wait is not a
33   * timed-out one. TODO selenium calls inside Wait are only logged once (filtered else) make this configurable TODO make name of a
34   * "Wait" class configurable TODO (feature) count time taken inside a Wait and logg that, too TODO (feature) add more metrics.
35   * currently verification errors can not be reliable counted
36   *
37   * @author Robert Zimmermann $Id: LoggingCommandProcessor.java 134 2009-01-14 20:44:21Z bobbyde $
38   */
39  public class LoggingCommandProcessor implements CommandProcessor {
40      static final String AUTO_SCREENSHOT_WAIT_TIMEOUT_FILENAME_PART = "WaitTimeout";
41  
42      private CommandProcessor realCommandProcessor;
43  
44      private LoggingResultsFormatter formatter;
45  
46      final TestMetricsBean seleniumTestMetrics = new TestMetricsBean();
47  
48      static final String SELENIUM_RC_OK_RESULT = "OK";
49  
50      static final String SELENIUM_RC_OK_RESULT_PREFIX_WITH_COMMA = SELENIUM_RC_OK_RESULT + ",";
51  
52      static final String SELENIUM_CORE_BOOLEAN_RESULT_TRUE = "true";
53  
54      static final String SELENIUM_CORE_BOOLEAN_RESULT_FALSE = "false";
55  
56      static final String WAIT_CLASS_NAME = "Wait";
57  
58      boolean logMethodsAsComments = true;
59  
60      String[] excludeCommandsFromLogging = {"getHtmlSource",};
61  
62      List<LoggingBean> loggingEventsQueue = new ArrayList<LoggingBean>();
63  
64      private LoggingNotifier callbackNotifier = null;
65      private Object callbackInstance = null;
66  
67      /**
68       * Constructor.
69       *
70       * @param commandProcessor
71       *        commandProcessor to be used for communication with selenium
72       * @param myFormatter
73       *        formatter, responsible for formating all loggingEvents and writing them to file, db or whatever.
74       */
75      public LoggingCommandProcessor(CommandProcessor commandProcessor, LoggingResultsFormatter myFormatter) {
76          this.formatter = myFormatter;
77          this.realCommandProcessor = commandProcessor;
78      }
79  
80      /**
81       * Will create an HttpCommandProcessor for you.
82       *
83       * @param serverHost -
84       *        the host name on which the Selenium Server resides
85       * @param serverPort -
86       *        the port on which the Selenium Server is listening
87       * @param browserStartCommand -
88       *        the command string used to launch the browser, e.g. "*firefox" or "c:\\program files\\internet
89       *        explorer\\iexplore.exe"
90       * @param browserUrl -
91       *        the starting URL including just a domain name. We'll start the browser pointing at the Selenium resources on this
92       *        URL, e.g. "http://www.google.com" would send the browser to
93       *        "http://www.google.com/selenium-server/core/RemoteRunner.html"
94       * @param myFormatter
95       *        formatter, responsible for formating all loggingEvents and writing them to file, db or whatever.
96       */
97      public LoggingCommandProcessor(String serverHost, int serverPort, String browserStartCommand, String browserUrl,
98              LoggingResultsFormatter myFormatter) {
99          this.formatter = myFormatter;
100         this.realCommandProcessor = new HttpCommandProcessor(serverHost, serverPort, browserStartCommand, browserUrl);
101     }
102 
103     /**
104      * Extends doCommand, handling special logging commands. Delegates all other commands to the realcommandProcessor.
105      * {@inheritDoc}
106      */
107     public String doCommand(String commandName, String[] args) {
108         String result = "";
109         long cmdStartMillis = System.currentTimeMillis();
110         if (SeleniumCommandExtensions.COMMAND_EXTENSION_LOG_COMMENT.getName().equals(commandName)) {
111             String comment = args[0] != null ? args[0] : "";
112             String extraInfo = "";
113             if (args.length > 1) {
114                 extraInfo = args[1] != null ? args[1] : "";
115             }
116             logComment(comment, extraInfo, cmdStartMillis);
117         } else if (SeleniumCommandExtensions.COMMAND_EXTENSION_LOG_AUTO_SCREENSHOT.getName().equals(commandName)) {
118             String baseName = args[0] != null ? args[0] : "";
119             doAutomaticScreenshot(baseName);
120         } else if (SeleniumCommandExtensions.COMMAND_EXTENSION_LOG_ASSERTION.getName().equals(commandName)) {
121             // FIXME handle less than 3 args
122             String[] loggingArgs = new String[] {args[1], args[2]};
123             doExceptionLogging(args[0], loggingArgs, "", null, cmdStartMillis);
124         } else if (SeleniumCommandExtensions.COMMAND_EXTENSION_LOG_RESOURCE.getName().equals(commandName)) {
125             result = LoggingCommandProcessor.SELENIUM_RC_OK_RESULT;
126             long now = System.currentTimeMillis();
127             LoggingBean b = new LoggingBean();
128             b.setCallingClass(getRealCallingClassWithLineNumberAsString(getCurrentCallingClassAsStackTraceElement()));
129             b.setWaitInvolved(isWaitInvolved());
130             b.setSourceMethod("RESOURCE");
131             b.setCommandName("captureScreenshot");
132             b.setResult(result);
133             b.setArgs(args);
134             b.setCommandSuccessful(true);
135             b.setCmdStartMillis(now);
136             b.setCmdEndMillis(now);
137             loggingEventsQueue.add(b);
138         } else {
139             this.seleniumTestMetrics.incCommandsProcessed();
140             try {
141                 result = this.realCommandProcessor.doCommand(commandName, args);
142             } catch (RuntimeException e) {
143                 doExceptionLogging(commandName, args, "", e, cmdStartMillis);
144                 throw e;
145             }
146             doLogging(commandName, args, result, cmdStartMillis);
147         }
148         return result;
149     }
150 
151     /**
152      * {@inheritDoc}
153      */
154     /*
155      * getScreenshot patch needed for this public BufferedImage getScreenshot(String fileType) { return
156      * this.realCommandProcessor.getScreenshot(fileType); }
157      */
158     /**
159      * {@inheritDoc}
160      */
161     public boolean getBoolean(String commandName, String[] args) {
162         // TODO: both?
163         long cmdStartMillis = System.currentTimeMillis();
164         this.seleniumTestMetrics.incCommandsProcessed();
165         this.seleniumTestMetrics.incVerificationsProcessed();
166         boolean result = false;
167         try {
168             result = this.realCommandProcessor.getBoolean(commandName, args);
169         } catch (RuntimeException e) {
170             doExceptionLogging(commandName, args, "", e, cmdStartMillis);
171             throw (e);
172         }
173         doLogging(commandName, args, LoggingCommandProcessor.SELENIUM_RC_OK_RESULT_PREFIX_WITH_COMMA + result, cmdStartMillis);
174         return result;
175     }
176 
177     /**
178      * {@inheritDoc}
179      */
180     public boolean[] getBooleanArray(String commandName, String[] args) {
181         long cmdStartMillis = System.currentTimeMillis();
182         this.seleniumTestMetrics.incCommandsProcessed();
183         boolean[] results;
184         try {
185             results = this.realCommandProcessor.getBooleanArray(commandName, args);
186         } catch (RuntimeException e) {
187             doExceptionLogging(commandName, args, "", e, cmdStartMillis);
188             throw e;
189         }
190         doLogging(commandName, args, LoggingCommandProcessor.SELENIUM_RC_OK_RESULT_PREFIX_WITH_COMMA
191                 + ArrayUtils.toString(results), cmdStartMillis);
192         return results;
193     }
194 
195     /**
196      * {@inheritDoc}
197      */
198     public Number getNumber(String commandName, String[] args) {
199         long cmdStartMillis = System.currentTimeMillis();
200         this.seleniumTestMetrics.incCommandsProcessed();
201         Number result;
202         try {
203             result = this.realCommandProcessor.getNumber(commandName, args);
204         } catch (RuntimeException e) {
205             doExceptionLogging(commandName, args, "", e, cmdStartMillis);
206             throw e;
207         }
208         doLogging(commandName, args, LoggingCommandProcessor.SELENIUM_RC_OK_RESULT_PREFIX_WITH_COMMA + result, cmdStartMillis);
209         return result;
210     }
211 
212     /**
213      * {@inheritDoc}
214      */
215     public Number[] getNumberArray(String commandName, String[] args) {
216         long cmdStartMillis = System.currentTimeMillis();
217         this.seleniumTestMetrics.incCommandsProcessed();
218         Number[] results;
219         try {
220             results = this.realCommandProcessor.getNumberArray(commandName, args);
221         } catch (RuntimeException e) {
222             doExceptionLogging(commandName, args, "", e, cmdStartMillis);
223             throw e;
224         }
225         doLogging(commandName, args, LoggingCommandProcessor.SELENIUM_RC_OK_RESULT_PREFIX_WITH_COMMA
226                 + ArrayUtils.toString(results), cmdStartMillis);
227         return results;
228     }
229 
230     /**
231      * {@inheritDoc}
232      */
233     public String getString(String commandName, String[] args) {
234         long cmdStartMillis = System.currentTimeMillis();
235         this.seleniumTestMetrics.incCommandsProcessed();
236         String result;
237         try {
238             result = this.realCommandProcessor.getString(commandName, args);
239         } catch (RuntimeException e) {
240             doExceptionLogging(commandName, args, "", e, cmdStartMillis);
241             throw e;
242         }
243         doLogging(commandName, args, LoggingCommandProcessor.SELENIUM_RC_OK_RESULT_PREFIX_WITH_COMMA
244                 + ArrayUtils.toString(result), cmdStartMillis);
245         return result;
246     }
247 
248     /**
249      * {@inheritDoc}
250      */
251     public String[] getStringArray(String commandName, String[] args) {
252         long cmdStartMillis = System.currentTimeMillis();
253         String[] results;
254         try {
255             results = this.realCommandProcessor.getStringArray(commandName, args);
256         } catch (RuntimeException e) {
257             doExceptionLogging(commandName, args, "", e, cmdStartMillis);
258             throw e;
259         }
260         doLogging(commandName, args, LoggingCommandProcessor.SELENIUM_RC_OK_RESULT_PREFIX_WITH_COMMA
261                 + ArrayUtils.toString(results), cmdStartMillis);
262         return results;
263     }
264 
265     /**
266      * {@inheritDoc}
267      */
268     public void start() {
269         this.realCommandProcessor.start();
270         this.seleniumTestMetrics.setStartTimeStamp(System.currentTimeMillis());
271         logExecutionEnvironment();
272     }
273 
274     /**
275      * {@inheritDoc}
276      */
277     public void stop() {
278         seleniumTestFinished();
279         this.realCommandProcessor.stop();
280         seleniumTestMetrics.setCommandsExcludedFromLogging(excludeCommandsFromLogging);
281         // TODO: looks a bit awkward (instantiating and not care about the instance)
282         new EventQueuePostProcessor(formatter, loggingEventsQueue, seleniumTestMetrics, logMethodsAsComments);
283     }
284 
285     /**
286      * List of Selenium commands to be excluded from logging. Default exclude: getHtmlSource
287      *
288      * @return current list of commands to be excluded
289      */
290     public String[] getExcludedCommands() {
291         return excludeCommandsFromLogging.clone();
292     }
293 
294     /**
295      * List of Selenium commands to be excluded from logging Be aware that the defaults will be overwritten. Combine with an
296      * getExcludedCommands to preserve defaults
297      *
298      * @param excludedCommands
299      *        list of commands to be excluded
300      */
301     public void setExcludedCommands(String[] excludedCommands) {
302         this.excludeCommandsFromLogging = excludedCommands.clone();
303     }
304 
305     /**
306      * Remember any selenium command with its result as an SeleniumLoggingBean. This is an convenience method to preset an
307      * SeleniumLoggingBean
308      *
309      * @param commandName
310      *        the commandName for and from selenium (may be a special one like for comments)
311      * @param args
312      *        0 to 2 parameters as used by selenium
313      * @param result
314      *        the result from selenium (and RC)
315      * @param cmdStartMillis
316      *        timestamp just before command started
317      * @param cmdEndMillis
318      *        timestamp after command finished
319      * @return preset SeleniumLoggingBean (only preset, as the SeleniumLoggingBean can hold more information)
320      */
321     public static LoggingBean presetLoggingBean(String commandName, String[] args, String result, long cmdStartMillis,
322             long cmdEndMillis) {
323         LoggingBean loggingBean = new LoggingBean();
324         loggingBean.setCommandName(commandName);
325         loggingBean.setArgs(args);
326         loggingBean.setResult(result);
327         loggingBean.setCmdStartMillis(cmdStartMillis);
328         loggingBean.setCmdEndMillis(cmdEndMillis);
329         return loggingBean;
330     }
331 
332     /**
333      * Gather information about where and with which versions selenium is executed. FIXME: use this.getEval to get all these
334      * commands logged the normal way and summarized later in the formatter
335      */
336     void logExecutionEnvironment() {
337         final String userAgent = getEvalNoException("navigator.userAgent");
338         this.seleniumTestMetrics.setUserAgent(userAgent);
339 
340         // SeleniumCore
341         final String seleniumCoreVersion = getEvalNoException("window.top.Selenium.coreVersion");
342         this.seleniumTestMetrics.setSeleniumCoreVersion(seleniumCoreVersion);
343         final String seleniumCoreRevision = getEvalNoException("window.top.Selenium.coreRevision");
344         this.seleniumTestMetrics.setSeleniumCoreRevision(seleniumCoreRevision);
345         // SeleniumRC
346         final String seleniumRcVersion = getEvalNoException("window.top.Selenium.rcVersion");
347         this.seleniumTestMetrics.setSeleniumRcVersion(seleniumRcVersion);
348         final String seleniumRcRevision = getEvalNoException("window.top.Selenium.rcRevision");
349         this.seleniumTestMetrics.setSeleniumRcRevision(seleniumRcRevision);
350     }
351 
352     /**
353      * Get an Property via Selenium getEval catching any Exception beeing thrown.
354      * @param jsExpr an JavaScript Expressing returning an String
355      * @return result of calling getEval or "UNKNOWN" if any Exception is issued by Selenium
356      */
357     String getEvalNoException(String jsExpr) {
358         String propertyValue;
359         try {
360             propertyValue = this.realCommandProcessor.getString("getEval",
361                 new String[] {jsExpr,});
362         } catch (Exception exc) {
363             propertyValue = "UNKNOWN";
364         }
365         return propertyValue;
366     }
367 
368     /**
369      * Log an Exception.
370      *
371      * @param commandName
372      *        commandName which possibly is responsible for the exception
373      * @param args
374      *        arguments which possibly are responsible for the exception
375      * @param result
376      *        normally empty string as the processed command caused an exception
377      * @param exception
378      *        the exception thrown by the used CommandProcessor can be null
379      */
380     void doExceptionLogging(String commandName, String[] args, String result, Throwable exception, long cmdStartMillis) {
381         Boolean screenshot = true;
382         if (null!=callbackNotifier) {
383             screenshot = callbackNotifier.errorLogging(callbackInstance, commandName, args, result, exception, cmdStartMillis);
384         }
385         if (screenshot) {
386             doAutomaticScreenshot("Error");
387         }
388         String resultContent;
389         String errorMessage;
390         if (null != exception) {
391             resultContent = "ERROR," + result + " " + exception.getClass().getName() + " - " + exception.getMessage();
392             errorMessage = exception.getMessage();
393         } else {
394             resultContent = "ERROR," + result;
395             if (args.length > 0) {
396                 errorMessage = "ERROR: " + args[0];
397             } else {
398                 errorMessage = "INTERNAL ERROR: real error-msg could not be determined";
399             }
400         }
401         doLogging(commandName, args, resultContent, cmdStartMillis);
402         this.seleniumTestMetrics.incFailedCommands();
403         this.seleniumTestMetrics.setLastFailedCommandMessage(errorMessage);
404     }
405 
406     /**
407      * Log the current Command.
408      *
409      * @param commandName
410      *        commandName to be logged
411      * @param args
412      *        arguments to be logged
413      * @param result
414      *        the result to be logged
415      * @param cmdStartMillis
416      *        time in milliseconds when execution started
417      */
418     void doLogging(String commandName, String[] args, String result, long cmdStartMillis) {
419         LoggingBean currentCommand = LoggingCommandProcessor.presetLoggingBean(commandName, args, result, cmdStartMillis, System
420                 .currentTimeMillis());
421         currentCommand.setExcludeFromLogging(isCommandExcludedFromLogging(commandName));
422         currentCommand.setCallingClass(getRealCallingClassWithLineNumberAsString(getCurrentCallingClassAsStackTraceElement()));
423         currentCommand.setWaitInvolved(isWaitInvolved());
424         String sourceMethodName = "unknown";
425         StackTraceElement classOrNull = getCurrentCallingClassAsStackTraceElement();
426         if (null != classOrNull) {
427             sourceMethodName = classOrNull.getMethodName();
428         }
429         currentCommand.setSourceMethod(sourceMethodName);
430         loggingEventsQueue.add(currentCommand);
431     }
432 
433     /**
434      * Log comment.
435      *
436      * @param comment
437      *        the comment to be logged
438      * @param extraInfo
439      *        optional, additional string to be logged, which may be treated a special way or omitted by the used formatter
440      */
441     void logComment(String comment, String extraInfo, long cmdStartMillis) {
442         doLogging(SeleniumCommandExtensions.COMMAND_EXTENSION_LOG_COMMENT.getName(), new String[] {comment, extraInfo}, "",
443                 cmdStartMillis);
444     }
445 
446     /**
447      * Utility to check if the current command is to be excluded.
448      *
449      * @param commandName
450      *        current command name
451      * @return true, if this command name should be excluded from logging
452      */
453     boolean isCommandExcludedFromLogging(final String commandName) {
454         return Arrays.asList(excludeCommandsFromLogging).contains(commandName);
455     }
456 
457     StackTraceElement getCurrentCallingClassAsStackTraceElement() {
458         return StackTraceUtils.getCurrentCallingClassAsStackTraceElement(Thread.currentThread().getStackTrace(),
459                 "DefaultSelenium");
460     }
461 
462     String getRealCallingClassWithLineNumberAsString(StackTraceElement currentCallingClassAsStackTraceElement) {
463         return StackTraceUtils.stackTraceElementWithLinenumberAsString(currentCallingClassAsStackTraceElement);
464     }
465 
466     boolean isWaitInvolved() {
467         return StackTraceUtils.isClassInStackTrace(Thread.currentThread().getStackTrace(), "."
468                 + LoggingCommandProcessor.WAIT_CLASS_NAME);
469     }
470 
471     void seleniumTestFinished() {
472         this.seleniumTestMetrics.setEndTimeStamp(System.currentTimeMillis());
473         // Wait timed out?
474         if (loggingEventsQueue.size() > 0) {
475             LoggingBean lastBeanInQueue = loggingEventsQueue.get(loggingEventsQueue.size() - 1);
476             if (lastBeanInQueue.isWaitInvolved()) {
477                 lastBeanInQueue.setResult("ERROR,wait timed out");
478                 doAutomaticScreenshot(LoggingCommandProcessor.AUTO_SCREENSHOT_WAIT_TIMEOUT_FILENAME_PART);
479                 this.seleniumTestMetrics.setLastFailedCommandMessage(lastBeanInQueue.getResult());
480                 this.seleniumTestMetrics.incFailedCommands();
481             }
482         }
483     }
484 
485     void doAutomaticScreenshot(String baseFileName) {
486         final String autoScreenshotFullPath = formatter.generateFilenameForAutomaticScreenshot(baseFileName);
487         Boolean internal = true;
488         if (null!=callbackNotifier) {
489             final String pathFile = formatter.generateFilenameForAutomaticScreenshot(
490                     LoggingCommandProcessor.AUTO_SCREENSHOT_WAIT_TIMEOUT_FILENAME_PART);
491             internal = callbackNotifier.makeScreenshot(callbackInstance, pathFile);
492         }
493         if (internal) {
494             doCommand("captureScreenshot", new String[] {autoScreenshotFullPath});
495         }
496     }
497 
498     /**
499      * Is the current test failed.
500      *
501      * Only suitable after all commands are processed.
502      * But can be called at any time.
503      *
504      * @return true if test failed
505      */
506     public boolean isTestFailed() {
507         return seleniumTestMetrics.getFailedCommands() > 0;
508     }
509 
510     /**
511      * Set the call back notifier. If you want to stop notifications
512      * set to null.
513      *
514      * @param callbackLoggingNotifier The call back notifier object
515      * @param callbackLoggingInstance The calling instance to notify
516      */
517     public void setCallbackNotifier(LoggingNotifier callbackLoggingNotifier, Object callbackLoggingInstance) {
518         this.callbackNotifier = callbackLoggingNotifier;
519         this.callbackInstance = callbackLoggingInstance;
520     }
521 
522     public boolean isLogMethodsAsComments() {
523         return logMethodsAsComments;
524     }
525 
526     public void setLogMethodsAsComments(boolean logMethodsAsComments) {
527         this.logMethodsAsComments = logMethodsAsComments;
528     }
529 }
530