Created
June 19, 2015 23:49
-
-
Save brianlucas/f234105fe3b611dbbfcf to your computer and use it in GitHub Desktop.
mvn clean install output
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| [ec2-user@ip-172-31-30-168 SeleniumGridScaler]$ mvn clean install | |
| [INFO] Scanning for projects... | |
| [INFO] | |
| [INFO] ------------------------------------------------------------------------ | |
| [INFO] Building selenium-grid-scaler 0.9-SNAPSHOT | |
| [INFO] ------------------------------------------------------------------------ | |
| [INFO] | |
| [INFO] --- maven-clean-plugin:2.5:clean (default-clean) @ selenium-grid-scaler --- | |
| [INFO] Deleting /home/ec2-user/SeleniumGridScaler/target | |
| [INFO] | |
| [INFO] --- cobertura-maven-plugin:2.6:clean (default) @ selenium-grid-scaler --- | |
| [INFO] | |
| [INFO] --- maven-resources-plugin:2.6:resources (default-resources) @ selenium-grid-scaler --- | |
| [WARNING] Using platform encoding (UTF-8 actually) to copy filtered resources, i.e. build is platform dependent! | |
| [INFO] Copying 7 resources | |
| [INFO] | |
| [INFO] --- maven-compiler-plugin:2.4:compile (default-compile) @ selenium-grid-scaler --- | |
| [WARNING] File encoding has not been set, using platform encoding UTF-8, i.e. build is platform dependent! | |
| [INFO] Compiling 23 source files to /home/ec2-user/SeleniumGridScaler/target/classes | |
| [INFO] | |
| [INFO] --- maven-resources-plugin:2.6:testResources (default-testResources) @ selenium-grid-scaler --- | |
| [WARNING] Using platform encoding (UTF-8 actually) to copy filtered resources, i.e. build is platform dependent! | |
| [INFO] skip non existing resourceDirectory /home/ec2-user/SeleniumGridScaler/src/test/resources | |
| [INFO] | |
| [INFO] --- maven-compiler-plugin:2.4:testCompile (default-testCompile) @ selenium-grid-scaler --- | |
| [WARNING] File encoding has not been set, using platform encoding UTF-8, i.e. build is platform dependent! | |
| [INFO] Compiling 27 source files to /home/ec2-user/SeleniumGridScaler/target/test-classes | |
| [INFO] | |
| [INFO] --- maven-surefire-plugin:2.12:test (default-test) @ selenium-grid-scaler --- | |
| [INFO] Surefire report directory: /home/ec2-user/SeleniumGridScaler/target/surefire-reports | |
| ------------------------------------------------------- | |
| T E S T S | |
| ------------------------------------------------------- | |
| Running com.rmn.qa.aws.VmManagerTest | |
| 23:48:56,596 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy] | |
| 23:48:56,597 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml] | |
| 23:48:56,597 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/home/ec2-user/SeleniumGridScaler/target/classes/logback.xml] | |
| 23:48:56,735 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender] | |
| 23:48:56,738 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT] | |
| 23:48:56,756 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property | |
| 23:48:56,801 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.FileAppender] | |
| 23:48:56,802 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE] | |
| 23:48:56,807 |-INFO in ch.qos.logback.core.FileAppender[FILE] - File property is set to [log/automation.log] | |
| 23:48:56,808 |-INFO in ch.qos.logback.classic.joran.action.LevelAction - com.rmn.qa.aws.AwsVmManager level set to INFO | |
| 23:48:56,809 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[com.rmn.qa.aws.AwsVmManager] | |
| 23:48:56,809 |-INFO in ch.qos.logback.classic.joran.action.LevelAction - com.rmn.qa.servlet.AutomationTestRunServlet level set to INFO | |
| 23:48:56,810 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[com.rmn.qa.servlet.AutomationTestRunServlet] | |
| 23:48:56,810 |-INFO in ch.qos.logback.classic.joran.action.LevelAction - com.rmn.qa.servlet.AutomationStatusServlet level set to INFO | |
| 23:48:56,810 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[com.rmn.qa.servlet.AutomationStatusServlet] | |
| 23:48:56,810 |-INFO in ch.qos.logback.classic.joran.action.LevelAction - com.rmn.qa.servlet.StatusServlet level set to INFO | |
| 23:48:56,810 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[com.rmn.qa.servlet.StatusServlet] | |
| 23:48:56,810 |-INFO in ch.qos.logback.classic.joran.action.LevelAction - com.rmn.qa.task.AbstractAutomationCleanupTask level set to INFO | |
| 23:48:56,810 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[com.rmn.qa.task.AbstractAutomationCleanupTask] | |
| 23:48:56,811 |-INFO in ch.qos.logback.classic.joran.action.LevelAction - com.rmn.qa.task.AutomationHubCleanupTask level set to INFO | |
| 23:48:56,811 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[com.rmn.qa.task.AutomationHubCleanupTask] | |
| 23:48:56,811 |-INFO in ch.qos.logback.classic.joran.action.LevelAction - com.rmn.qa.task.AutomationNodeCleanupTask level set to INFO | |
| 23:48:56,811 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[com.rmn.qa.task.AutomationNodeCleanupTask] | |
| 23:48:56,811 |-INFO in ch.qos.logback.classic.joran.action.LevelAction - com.rmn.qa.task.AutomationNodeRegistryTask level set to INFO | |
| 23:48:56,811 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[com.rmn.qa.task.AutomationNodeRegistryTask] | |
| 23:48:56,811 |-INFO in ch.qos.logback.classic.joran.action.LevelAction - com.rmn.qa.task.AutomationHubCleanupTask level set to INFO | |
| 23:48:56,812 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[com.rmn.qa.task.AutomationHubCleanupTask] | |
| 23:48:56,812 |-INFO in ch.qos.logback.classic.joran.action.LevelAction - com.rmn.qa.task.AutomationReaperTask level set to INFO | |
| 23:48:56,812 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[com.rmn.qa.task.AutomationReaperTask] | |
| 23:48:56,812 |-INFO in ch.qos.logback.classic.joran.action.LevelAction - com.rmn.qa.AutomationCapabilityMatcher level set to INFO | |
| 23:48:56,812 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[com.rmn.qa.AutomationCapabilityMatcher] | |
| 23:48:56,812 |-INFO in ch.qos.logback.classic.joran.action.LevelAction - com.rmn.qa.AutomationRunContext level set to INFO | |
| 23:48:56,812 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[com.rmn.qa.AutomationRunContext] | |
| 23:48:56,813 |-INFO in ch.qos.logback.classic.joran.action.LevelAction - com.rmn.qa.AutomationRequestMatcher level set to INFO | |
| 23:48:56,813 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[com.rmn.qa.AutomationRequestMatcher] | |
| 23:48:56,813 |-INFO in ch.qos.logback.classic.joran.action.LevelAction - com.rmn.qa.aws.AwsTagReporter level set to INFO | |
| 23:48:56,813 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[com.rmn.qa.aws.AwsTagReporter] | |
| 23:48:56,813 |-INFO in ch.qos.logback.classic.joran.action.LevelAction - com.rmn.qa.AutomationContext level set to INFO | |
| 23:48:56,813 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[com.rmn.qa.AutomationContext] | |
| 23:48:56,813 |-INFO in ch.qos.logback.classic.joran.action.LevelAction - ROOT level set to INFO | |
| 23:48:56,813 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT] | |
| 23:48:56,813 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration. | |
| 23:48:56,815 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@28226e75 - Registering current configuration as safe fallback point | |
| Jun 19, 2015 23:48:56:834 PM - INFO [main] [AwsVmManager] Setting image id: null | |
| Jun 19, 2015 23:48:56:836 PM - INFO [main] [AwsVmManager] Setting instance type: null | |
| Jun 19, 2015 23:48:56:837 PM - INFO [main] [AwsVmManager] Sending run request to AWS... | |
| Jun 19, 2015 23:48:56:837 PM - INFO [main] [AwsVmManager] Run request result returned. Adding tags | |
| Jun 19, 2015 23:48:56:848 PM - INFO [TagReporter-Fri Jun 19 23:48:56 UTC 2015] [AwsTagReporter] AwsTagReporter thread initialized | |
| Jun 19, 2015 23:48:56:849 PM - ERROR [TagReporter-Fri Jun 19 23:48:56 UTC 2015] [AwsTagReporter] Error finding instances. Sleeping. | |
| Jun 19, 2015 23:48:56:852 PM - INFO [main] [AwsVmManager] Setting image id: linuxImage | |
| Jun 19, 2015 23:48:56:852 PM - INFO [main] [AwsVmManager] Setting instance type: null | |
| Jun 19, 2015 23:48:56:852 PM - INFO [main] [AwsVmManager] Setting subnet: subnetId | |
| Jun 19, 2015 23:48:56:852 PM - INFO [main] [AwsVmManager] Setting security group(s): securityGroup | |
| Jun 19, 2015 23:48:56:853 PM - INFO [main] [AwsVmManager] Setting keyname:keyName | |
| Jun 19, 2015 23:48:56:853 PM - INFO [main] [AwsVmManager] Sending run request to AWS... | |
| Jun 19, 2015 23:48:56:853 PM - INFO [main] [AwsVmManager] Run request result returned. Adding tags | |
| Jun 19, 2015 23:48:56:856 PM - INFO [TagReporter-Fri Jun 19 23:48:56 UTC 2015] [AwsTagReporter] AwsTagReporter thread initialized | |
| Jun 19, 2015 23:48:56:857 PM - ERROR [TagReporter-Fri Jun 19 23:48:56 UTC 2015] [AwsTagReporter] Error finding instances. Sleeping. | |
| Jun 19, 2015 23:48:56:860 PM - INFO [main] [AwsVmManager] Setting image id: linuxImage | |
| Jun 19, 2015 23:48:56:860 PM - INFO [main] [AwsVmManager] Setting instance type: null | |
| Jun 19, 2015 23:48:56:860 PM - INFO [main] [AwsVmManager] Setting subnet: subnetId | |
| Jun 19, 2015 23:48:56:860 PM - INFO [main] [AwsVmManager] Setting security group(s): securityGroup1 | |
| Jun 19, 2015 23:48:56:860 PM - INFO [main] [AwsVmManager] Setting security group(s): securityGroup2 | |
| Jun 19, 2015 23:48:56:861 PM - INFO [main] [AwsVmManager] Setting security group(s): securityGroup3 | |
| Jun 19, 2015 23:48:56:861 PM - INFO [main] [AwsVmManager] Setting keyname:keyName | |
| Jun 19, 2015 23:48:56:861 PM - INFO [main] [AwsVmManager] Sending run request to AWS... | |
| Jun 19, 2015 23:48:56:861 PM - INFO [main] [AwsVmManager] Run request result returned. Adding tags | |
| Jun 19, 2015 23:48:56:864 PM - INFO [TagReporter-Fri Jun 19 23:48:56 UTC 2015] [AwsTagReporter] AwsTagReporter thread initialized | |
| Jun 19, 2015 23:48:56:865 PM - ERROR [TagReporter-Fri Jun 19 23:48:56 UTC 2015] [AwsTagReporter] Error finding instances. Sleeping. | |
| Jun 19, 2015 23:48:56:868 PM - INFO [main] [AwsVmManager] Setting image id: windowsImage | |
| Jun 19, 2015 23:48:56:868 PM - INFO [main] [AwsVmManager] Setting instance type: null | |
| Jun 19, 2015 23:48:56:868 PM - INFO [main] [AwsVmManager] Setting subnet: subnetId | |
| Jun 19, 2015 23:48:56:868 PM - INFO [main] [AwsVmManager] Setting security group(s): securityGroup | |
| Jun 19, 2015 23:48:56:868 PM - INFO [main] [AwsVmManager] Setting keyname:keyName | |
| Jun 19, 2015 23:48:56:869 PM - INFO [main] [AwsVmManager] Sending run request to AWS... | |
| Jun 19, 2015 23:48:56:869 PM - INFO [main] [AwsVmManager] Run request result returned. Adding tags | |
| Jun 19, 2015 23:48:56:873 PM - INFO [TagReporter-Fri Jun 19 23:48:56 UTC 2015] [AwsTagReporter] AwsTagReporter thread initialized | |
| Jun 19, 2015 23:48:56:873 PM - ERROR [TagReporter-Fri Jun 19 23:48:56 UTC 2015] [AwsTagReporter] Error finding instances. Sleeping. | |
| Jun 19, 2015 23:48:56:910 PM - ERROR [main] [AwsVmManager] Machine state for id foo should be terminated (48) or shutting down (32) but was 8 instead | |
| Jun 19, 2015 23:48:56:917 PM - ERROR [main] [AwsVmManager] Matching terminated instance was not found for instance foo | |
| Jun 19, 2015 23:48:56:931 PM - ERROR [main] [AwsVmManager] Matching terminated instance was not found for instance foo | |
| Jun 19, 2015 23:48:56:968 PM - INFO [main] [AwsVmManager] Setting image id: null | |
| Jun 19, 2015 23:48:56:968 PM - INFO [main] [AwsVmManager] Setting instance type: null | |
| Jun 19, 2015 23:48:56:968 PM - INFO [main] [AwsVmManager] Setting subnet: subnetId | |
| Jun 19, 2015 23:48:56:968 PM - INFO [main] [AwsVmManager] Setting security group(s): securityGroup | |
| Jun 19, 2015 23:48:56:968 PM - INFO [main] [AwsVmManager] Setting keyname:keyName | |
| Jun 19, 2015 23:48:56:968 PM - INFO [main] [AwsVmManager] Sending run request to AWS... | |
| Jun 19, 2015 23:48:56:968 PM - ERROR [main] [AwsVmManager] Insufficient capacity in subnet [subnetId]: com.amazonaws.AmazonServiceException: message (Service: null; Status Code: 0; Error Code: InsufficientInstanceCapacity; Request ID: null) | |
| Jun 19, 2015 23:48:56:974 PM - INFO [main] [AwsVmManager] Setting image id: null | |
| Jun 19, 2015 23:48:56:974 PM - INFO [main] [AwsVmManager] Setting instance type: null | |
| Jun 19, 2015 23:48:56:974 PM - INFO [main] [AwsVmManager] Setting subnet: subnetId | |
| Jun 19, 2015 23:48:56:974 PM - INFO [main] [AwsVmManager] Setting security group(s): securityGroup | |
| Jun 19, 2015 23:48:56:974 PM - INFO [main] [AwsVmManager] Setting keyname:keyName | |
| Jun 19, 2015 23:48:56:975 PM - INFO [main] [AwsVmManager] Sending run request to AWS... | |
| Jun 19, 2015 23:48:56:975 PM - ERROR [main] [AwsVmManager] Insufficient capacity in subnet [subnetId]: com.amazonaws.AmazonServiceException: message (Service: null; Status Code: 0; Error Code: InsufficientInstanceCapacity; Request ID: null) | |
| Jun 19, 2015 23:48:56:975 PM - INFO [main] [AwsVmManager] Setting fallback subnet: fallback | |
| Jun 19, 2015 23:48:56:975 PM - INFO [main] [AwsVmManager] Run request result returned. Adding tags | |
| Jun 19, 2015 23:48:56:981 PM - INFO [main] [AwsVmManager] Setting image id: null | |
| Jun 19, 2015 23:48:56:981 PM - INFO [main] [AwsVmManager] Setting instance type: null | |
| Jun 19, 2015 23:48:56:981 PM - INFO [main] [AwsVmManager] Setting subnet: subnetId | |
| Jun 19, 2015 23:48:56:981 PM - INFO [main] [AwsVmManager] Setting security group(s): securityGroup | |
| Jun 19, 2015 23:48:56:981 PM - INFO [main] [AwsVmManager] Setting keyname:keyName | |
| Jun 19, 2015 23:48:56:981 PM - INFO [main] [AwsVmManager] Sending run request to AWS... | |
| Jun 19, 2015 23:48:56:993 PM - INFO [TagReporter-Fri Jun 19 23:48:56 UTC 2015] [AwsTagReporter] AwsTagReporter thread initialized | |
| Jun 19, 2015 23:48:56:993 PM - ERROR [TagReporter-Fri Jun 19 23:48:56 UTC 2015] [AwsTagReporter] Error finding instances. Sleeping. | |
| Jun 19, 2015 23:48:56:997 PM - INFO [main] [AwsVmManager] Setting image id: null | |
| Jun 19, 2015 23:48:56:998 PM - INFO [main] [AwsVmManager] Setting instance type: null | |
| Jun 19, 2015 23:48:56:998 PM - INFO [main] [AwsVmManager] Setting subnet: subnetId | |
| Jun 19, 2015 23:48:56:998 PM - INFO [main] [AwsVmManager] Setting security group(s): securityGroup | |
| Jun 19, 2015 23:48:56:998 PM - INFO [main] [AwsVmManager] Setting keyname:keyName | |
| Jun 19, 2015 23:48:56:998 PM - INFO [main] [AwsVmManager] Sending run request to AWS... | |
| Jun 19, 2015 23:48:56:998 PM - ERROR [main] [AwsVmManager] Insufficient capacity in subnet [subnetId]: com.amazonaws.AmazonServiceException: message (Service: null; Status Code: 0; Error Code: InsufficientInstanceCapacity; Request ID: null) | |
| Jun 19, 2015 23:48:56:998 PM - INFO [main] [AwsVmManager] Setting fallback subnet: foo | |
| Jun 19, 2015 23:48:56:999 PM - ERROR [main] [AwsVmManager] Insufficient capacity in subnet [foo]: com.amazonaws.AmazonServiceException: message (Service: null; Status Code: 0; Error Code: InsufficientInstanceCapacity; Request ID: null) | |
| Jun 19, 2015 23:48:56:999 PM - INFO [main] [AwsVmManager] Setting fallback subnet: foo | |
| Jun 19, 2015 23:48:56:999 PM - ERROR [main] [AwsVmManager] Insufficient capacity in subnet [foo]: com.amazonaws.AmazonServiceException: message (Service: null; Status Code: 0; Error Code: InsufficientInstanceCapacity; Request ID: null) | |
| Jun 19, 2015 23:48:56:999 PM - INFO [main] [AwsVmManager] Setting fallback subnet: foo | |
| Jun 19, 2015 23:48:56:999 PM - ERROR [main] [AwsVmManager] Insufficient capacity in subnet [foo]: com.amazonaws.AmazonServiceException: message (Service: null; Status Code: 0; Error Code: InsufficientInstanceCapacity; Request ID: null) | |
| Jun 19, 2015 23:48:56:999 PM - INFO [main] [AwsVmManager] Setting fallback subnet: foo | |
| Jun 19, 2015 23:48:57:000 PM - ERROR [main] [AwsVmManager] Insufficient capacity in subnet [foo]: com.amazonaws.AmazonServiceException: message (Service: null; Status Code: 0; Error Code: InsufficientInstanceCapacity; Request ID: null) | |
| Jun 19, 2015 23:48:57:005 PM - INFO [main] [AwsVmManager] Falling back to IAM roles for authorization since no credentials provided in system properties | |
| java.lang.IllegalArgumentException: AWS Access Key must be passed in by the [awsAccessKey] system property or be present in the AWS config file | |
| at com.rmn.qa.aws.AwsVmManager.getCredentials(AwsVmManager.java:158) ~[classes/:na] | |
| at com.rmn.qa.aws.AwsVmManager.<init>(AwsVmManager.java:91) ~[classes/:na] | |
| at com.rmn.qa.aws.VmManagerTest.testClientInitialized(VmManagerTest.java:606) [test-classes/:na] | |
| at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_79] | |
| at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_79] | |
| at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_79] | |
| at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_79] | |
| at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44) [junit-4.8.1.jar:na] | |
| at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15) [junit-4.8.1.jar:na] | |
| at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41) [junit-4.8.1.jar:na] | |
| at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20) [junit-4.8.1.jar:na] | |
| at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31) [junit-4.8.1.jar:na] | |
| at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76) [junit-4.8.1.jar:na] | |
| at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50) [junit-4.8.1.jar:na] | |
| at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193) [junit-4.8.1.jar:na] | |
| at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52) [junit-4.8.1.jar:na] | |
| at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191) [junit-4.8.1.jar:na] | |
| at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42) [junit-4.8.1.jar:na] | |
| at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184) [junit-4.8.1.jar:na] | |
| at org.junit.runners.ParentRunner.run(ParentRunner.java:236) [junit-4.8.1.jar:na] | |
| at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:236) [surefire-junit4-2.12.jar:2.12] | |
| at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:134) [surefire-junit4-2.12.jar:2.12] | |
| at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:113) [surefire-junit4-2.12.jar:2.12] | |
| at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_79] | |
| at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_79] | |
| at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_79] | |
| at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_79] | |
| at org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:189) [surefire-api-2.12.jar:2.12] | |
| at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:165) [surefire-booter-2.12.jar:2.12] | |
| at org.apache.maven.surefire.booter.ProviderFactory.invokeProvider(ProviderFactory.java:85) [surefire-booter-2.12.jar:2.12] | |
| at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:103) [surefire-booter-2.12.jar:2.12] | |
| at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:74) [surefire-booter-2.12.jar:2.12] | |
| Jun 19, 2015 23:48:57:014 PM - INFO [main] [AwsVmManager] Setting image id: foo | |
| Jun 19, 2015 23:48:57:014 PM - INFO [main] [AwsVmManager] Setting instance type: bar | |
| Jun 19, 2015 23:48:57:014 PM - INFO [main] [AwsVmManager] Sending run request to AWS... | |
| Jun 19, 2015 23:48:57:350 PM - ERROR [TagReporter-Fri Jun 19 23:48:56 UTC 2015] [AwsTagReporter] Error finding instances. Sleeping. | |
| Jun 19, 2015 23:48:57:357 PM - ERROR [TagReporter-Fri Jun 19 23:48:56 UTC 2015] [AwsTagReporter] Error finding instances. Sleeping. | |
| Jun 19, 2015 23:48:57:365 PM - ERROR [TagReporter-Fri Jun 19 23:48:56 UTC 2015] [AwsTagReporter] Error finding instances. Sleeping. | |
| Jun 19, 2015 23:48:57:373 PM - ERROR [TagReporter-Fri Jun 19 23:48:56 UTC 2015] [AwsTagReporter] Error finding instances. Sleeping. | |
| Jun 19, 2015 23:48:57:494 PM - ERROR [TagReporter-Fri Jun 19 23:48:56 UTC 2015] [AwsTagReporter] Error finding instances. Sleeping. | |
| Jun 19, 2015 23:48:57:850 PM - ERROR [TagReporter-Fri Jun 19 23:48:56 UTC 2015] [AwsTagReporter] Error finding instances. Sleeping. | |
| Jun 19, 2015 23:48:57:858 PM - ERROR [TagReporter-Fri Jun 19 23:48:56 UTC 2015] [AwsTagReporter] Error finding instances. Sleeping. | |
| Jun 19, 2015 23:48:57:866 PM - ERROR [TagReporter-Fri Jun 19 23:48:56 UTC 2015] [AwsTagReporter] Error finding instances. Sleeping. | |
| Jun 19, 2015 23:48:57:866 PM - INFO [main] [AwsVmManager] Setting image id: foo | |
| Jun 19, 2015 23:48:57:866 PM - INFO [main] [AwsVmManager] Setting instance type: bar | |
| Jun 19, 2015 23:48:57:867 PM - INFO [main] [AwsVmManager] Sending run request to AWS... | |
| Tests run: 26, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.982 sec | |
| Running com.rmn.qa.aws.AwsTagReporterTest | |
| Jun 19, 2015 23:48:57:874 PM - ERROR [TagReporter-Fri Jun 19 23:48:56 UTC 2015] [AwsTagReporter] Error finding instances. Sleeping. | |
| Jun 19, 2015 23:48:57:879 PM - INFO [main] [AwsTagReporter] AwsTagReporter thread initialized | |
| Jun 19, 2015 23:48:57:880 PM - INFO [main] [AwsTagReporter] Correct instances were found to add tags to! | |
| Jun 19, 2015 23:48:57:880 PM - INFO [main] [AwsTagReporter] Associating tags to instance: null | |
| Jun 19, 2015 23:48:57:881 PM - ERROR [main] [AwsTagReporter] Error adding tags. Please make sure your tag syntax is correct (refer to the readme) | |
| java.lang.ArrayIndexOutOfBoundsException: 1 | |
| at com.rmn.qa.aws.AwsTagReporter.setTagsForInstance(AwsTagReporter.java:117) [classes/:na] | |
| at com.rmn.qa.aws.AwsTagReporter.associateTags(AwsTagReporter.java:96) [classes/:na] | |
| at com.rmn.qa.aws.AwsTagReporter.run(AwsTagReporter.java:78) [classes/:na] | |
| at com.rmn.qa.aws.AwsTagReporterTest.testExceptionCaught(AwsTagReporterTest.java:58) [test-classes/:na] | |
| at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_79] | |
| at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_79] | |
| at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_79] | |
| at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_79] | |
| at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44) [junit-4.8.1.jar:na] | |
| at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15) [junit-4.8.1.jar:na] | |
| at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41) [junit-4.8.1.jar:na] | |
| at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20) [junit-4.8.1.jar:na] | |
| at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76) [junit-4.8.1.jar:na] | |
| at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50) [junit-4.8.1.jar:na] | |
| at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193) [junit-4.8.1.jar:na] | |
| at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52) [junit-4.8.1.jar:na] | |
| at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191) [junit-4.8.1.jar:na] | |
| at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42) [junit-4.8.1.jar:na] | |
| at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184) [junit-4.8.1.jar:na] | |
| at org.junit.runners.ParentRunner.run(ParentRunner.java:236) [junit-4.8.1.jar:na] | |
| at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:236) [surefire-junit4-2.12.jar:2.12] | |
| at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:134) [surefire-junit4-2.12.jar:2.12] | |
| at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:113) [surefire-junit4-2.12.jar:2.12] | |
| at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_79] | |
| at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_79] | |
| at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_79] | |
| at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_79] | |
| at org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:189) [surefire-api-2.12.jar:2.12] | |
| at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:165) [surefire-booter-2.12.jar:2.12] | |
| at org.apache.maven.surefire.booter.ProviderFactory.invokeProvider(ProviderFactory.java:85) [surefire-booter-2.12.jar:2.12] | |
| at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:103) [surefire-booter-2.12.jar:2.12] | |
| at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:74) [surefire-booter-2.12.jar:2.12] | |
| Jun 19, 2015 23:48:57:881 PM - INFO [main] [AwsTagReporter] AwsTagReporter thread completed successfully | |
| Jun 19, 2015 23:48:57:887 PM - INFO [main] [AwsTagReporter] AwsTagReporter thread initialized | |
| Jun 19, 2015 23:48:57:887 PM - ERROR [main] [AwsTagReporter] Error finding instances. Sleeping. | |
| Jun 19, 2015 23:48:57:887 PM - INFO [main] [AwsTagReporter] Correct instances were found to add tags to! | |
| Jun 19, 2015 23:48:57:887 PM - INFO [main] [AwsTagReporter] Associating tags to instance: null | |
| Jun 19, 2015 23:48:57:888 PM - INFO [main] [AwsTagReporter] Adding hard-coded tag: {Key: LaunchSource,Value: SeleniumGridScalerPlugin} | |
| Jun 19, 2015 23:48:57:889 PM - INFO [main] [AwsTagReporter] Tags added! | |
| Jun 19, 2015 23:48:57:889 PM - INFO [main] [AwsTagReporter] AwsTagReporter thread completed successfully | |
| Jun 19, 2015 23:48:57:894 PM - INFO [main] [AwsTagReporter] AwsTagReporter thread initialized | |
| Jun 19, 2015 23:48:57:895 PM - INFO [main] [AwsTagReporter] Correct instances were found to add tags to! | |
| Jun 19, 2015 23:48:57:895 PM - INFO [main] [AwsTagReporter] Associating tags to instance: null | |
| Jun 19, 2015 23:48:57:895 PM - INFO [main] [AwsTagReporter] Adding tag: {Key: key,Value: value} | |
| Jun 19, 2015 23:48:57:895 PM - INFO [main] [AwsTagReporter] Adding hard-coded tag: {Key: LaunchSource,Value: SeleniumGridScalerPlugin} | |
| Jun 19, 2015 23:48:57:895 PM - INFO [main] [AwsTagReporter] Tags added! | |
| Jun 19, 2015 23:48:57:896 PM - INFO [main] [AwsTagReporter] AwsTagReporter thread completed successfully | |
| Jun 19, 2015 23:48:57:901 PM - INFO [main] [AwsTagReporter] AwsTagReporter thread initialized | |
| Jun 19, 2015 23:48:57:901 PM - ERROR [main] [AwsTagReporter] Error finding instances. Sleeping. | |
| Jun 19, 2015 23:48:57:902 PM - ERROR [main] [AwsTagReporter] Error sleeping for adding tags | |
| java.lang.InterruptedException: null | |
| at com.rmn.qa.aws.AwsTagReporterTest$2.sleep(AwsTagReporterTest.java:101) ~[test-classes/:na] | |
| at com.rmn.qa.aws.AwsTagReporter.run(AwsTagReporter.java:72) ~[classes/:na] | |
| at com.rmn.qa.aws.AwsTagReporterTest.testSleepThrowsErrors(AwsTagReporterTest.java:104) [test-classes/:na] | |
| at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_79] | |
| at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_79] | |
| at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_79] | |
| at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_79] | |
| at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44) [junit-4.8.1.jar:na] | |
| at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15) [junit-4.8.1.jar:na] | |
| at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41) [junit-4.8.1.jar:na] | |
| at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20) [junit-4.8.1.jar:na] | |
| at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76) [junit-4.8.1.jar:na] | |
| at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50) [junit-4.8.1.jar:na] | |
| at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193) [junit-4.8.1.jar:na] | |
| at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52) [junit-4.8.1.jar:na] | |
| at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191) [junit-4.8.1.jar:na] | |
| at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42) [junit-4.8.1.jar:na] | |
| at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184) [junit-4.8.1.jar:na] | |
| at org.junit.runners.ParentRunner.run(ParentRunner.java:236) [junit-4.8.1.jar:na] | |
| at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:236) [surefire-junit4-2.12.jar:2.12] | |
| at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:134) [surefire-junit4-2.12.jar:2.12] | |
| at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:113) [surefire-junit4-2.12.jar:2.12] | |
| at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_79] | |
| at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_79] | |
| at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_79] | |
| at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_79] | |
| at org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:189) [surefire-api-2.12.jar:2.12] | |
| at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:165) [surefire-booter-2.12.jar:2.12] | |
| at org.apache.maven.surefire.booter.ProviderFactory.invokeProvider(ProviderFactory.java:85) [surefire-booter-2.12.jar:2.12] | |
| at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:103) [surefire-booter-2.12.jar:2.12] | |
| at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:74) [surefire-booter-2.12.jar:2.12] | |
| Jun 19, 2015 23:48:57:902 PM - INFO [main] [AwsTagReporter] Correct instances were found to add tags to! | |
| Jun 19, 2015 23:48:57:902 PM - INFO [main] [AwsTagReporter] Associating tags to instance: null | |
| Jun 19, 2015 23:48:57:903 PM - INFO [main] [AwsTagReporter] Adding hard-coded tag: {Key: LaunchSource,Value: SeleniumGridScalerPlugin} | |
| Jun 19, 2015 23:48:57:903 PM - INFO [main] [AwsTagReporter] Tags added! | |
| Jun 19, 2015 23:48:57:903 PM - INFO [main] [AwsTagReporter] AwsTagReporter thread completed successfully | |
| Jun 19, 2015 23:48:57:908 PM - INFO [main] [AwsTagReporter] AwsTagReporter thread initialized | |
| Tests run: 5, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.034 sec | |
| Running com.rmn.qa.AutomationRunContextTest | |
| Jun 19, 2015 23:48:57:927 PM - WARN [main] [AutomationContext] Defaulting node count to 150 | |
| Jun 19, 2015 23:48:57:930 PM - INFO [main] [AutomationRunContext] Tracked test run [uuid] found with no running tests. Adding to set for removal. | |
| Jun 19, 2015 23:48:57:930 PM - WARN [main] [AutomationRunContext] Removing run because it has no more running test slots. UUID [uuid] | |
| Jun 19, 2015 23:48:57:931 PM - INFO [main] [AutomationRunContext] Run [uuid] is not at least [90] seconds old. Will not analyze. | |
| Jun 19, 2015 23:48:57:931 PM - WARN [main] [AutomationRunContext] No runs found to clean up | |
| Jun 19, 2015 23:48:57:932 PM - INFO [main] [AutomationRunContext] Run [uuid] is not at least [90] seconds old. Will not analyze. | |
| Jun 19, 2015 23:48:57:932 PM - WARN [main] [AutomationRunContext] No runs found to clean up | |
| Jun 19, 2015 23:48:57:933 PM - INFO [main] [AutomationRunContext] Tracked test run [uuid] found with no running tests. Adding to set for removal. | |
| Jun 19, 2015 23:48:57:933 PM - WARN [main] [AutomationRunContext] Removing run because it has no more running test slots. UUID [uuid] | |
| Jun 19, 2015 11:48:57 PM org.openqa.grid.internal.TestSlot getNewSession | |
| INFO: Trying to create a new session on test slot {uuid=uuid} | |
| Jun 19, 2015 23:48:57:946 PM - WARN [main] [AutomationRunContext] No runs found to clean up | |
| Jun 19, 2015 23:48:57:946 PM - INFO [main] [AutomationRunContext] Tracked test run [uuid] found with no running tests. Adding to set for removal. | |
| Jun 19, 2015 23:48:57:946 PM - WARN [main] [AutomationRunContext] Removing run because it has no more running test slots. UUID [uuid] | |
| Exception in thread "TagReporter-Fri Jun 19 23:48:56 UTC 2015" java.lang.RuntimeException: Error waiting for instances to exist to add tags | |
| at com.rmn.qa.aws.AwsTagReporter.run(AwsTagReporter.java:61) | |
| Jun 19, 2015 11:48:58 PM org.openqa.grid.internal.TestSlot getNewSession | |
| INFO: Trying to create a new session on test slot {platform=linux, browserName=chrome} | |
| Jun 19, 2015 23:48:58:017 PM - INFO [main] [AutomationRunContext] Untracked test found. Adding. | |
| Jun 19, 2015 23:48:58:017 PM - INFO [main] [AutomationRunContext] Untracked test found. Adding. | |
| Jun 19, 2015 23:48:58:017 PM - INFO [main] [AutomationRunContext] Untracked test found. Adding. | |
| Jun 19, 2015 23:48:58:017 PM - INFO [main] [AutomationRunContext] Untracked test found. Adding. | |
| Jun 19, 2015 23:48:58:017 PM - INFO [main] [AutomationRunContext] Untracked test found. Adding. | |
| Jun 19, 2015 23:48:58:018 PM - INFO [main] [AutomationRunContext] Adding 5 tests to the total in progress count 0 | |
| Jun 19, 2015 23:48:58:018 PM - INFO [main] [AutomationRunContext] Returning 5 free capacity for the hub | |
| Jun 19, 2015 11:48:58 PM org.openqa.grid.internal.TestSlot getNewSession | |
| INFO: Trying to create a new session on test slot {platform=linux, browserName=chrome, uuid=testUuid} | |
| Jun 19, 2015 23:48:58:019 PM - INFO [main] [AutomationRunContext] Adding 5 in progress tests for test run [testUuid] | |
| Jun 19, 2015 23:48:58:020 PM - INFO [main] [AutomationRunContext] Returning 5 free capacity for the hub | |
| Jun 19, 2015 11:48:58 PM org.openqa.grid.internal.TestSlot getNewSession | |
| INFO: Trying to create a new session on test slot {platform=linux, browserName=chrome, uuid=testUuid} | |
| Jun 19, 2015 23:48:58:021 PM - INFO [main] [AutomationRunContext] Adding 10 for test run [testUuid] | |
| Jun 19, 2015 23:48:58:021 PM - INFO [main] [AutomationRunContext] Returning 0 free capacity for the hub | |
| Jun 19, 2015 11:48:58 PM org.openqa.grid.internal.TestSlot getNewSession | |
| INFO: Trying to create a new session on test slot {platform=linux, browserName=chrome, uuid=testUuid} | |
| Jun 19, 2015 23:48:58:022 PM - INFO [main] [AutomationRunContext] Adding 5 in progress tests for test run [testUuid] | |
| Jun 19, 2015 23:48:58:023 PM - INFO [main] [AutomationRunContext] Returning 5 free capacity for the hub | |
| Tests run: 13, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.116 sec | |
| Running com.rmn.qa.AutomationRequestMatcherTest | |
| Jun 19, 2015 23:48:58:031 PM - INFO [main] [AutomationRequestMatcher] Analyzing node nodeId... | |
| Jun 19, 2015 23:48:58:031 PM - INFO [main] [AutomationRequestMatcher] Node had 0 matching running sessions and 1 matching capable slots | |
| Jun 19, 2015 23:48:58:032 PM - INFO [main] [AutomationRequestMatcher] Node marked for termination. Subtracting 0 sessions from 0 total free slots | |
| Jun 19, 2015 23:48:58:032 PM - INFO [main] [AutomationRequestMatcher] Returning 0 free slots for request Run Request - Browser: firefox | |
| Jun 19, 2015 23:48:58:033 PM - INFO [main] [AutomationRequestMatcher] Analyzing node nodeId... | |
| Jun 19, 2015 23:48:58:033 PM - INFO [main] [AutomationRequestMatcher] Node had 0 matching running sessions and 10 matching capable slots | |
| Jun 19, 2015 23:48:58:034 PM - INFO [main] [AutomationRequestMatcher] Returning 10 free slots for request Run Request - Browser: firefox - OS: linux | |
| Jun 19, 2015 23:48:58:034 PM - INFO [main] [AutomationRequestMatcher] Analyzing node... | |
| Jun 19, 2015 23:48:58:034 PM - INFO [main] [AutomationRequestMatcher] Node had 0 matching running sessions and 1 matching capable slots | |
| Jun 19, 2015 23:48:58:035 PM - INFO [main] [AutomationRequestMatcher] Returning 1 free slots for request Run Request - Browser: firefox | |
| Jun 19, 2015 23:48:58:035 PM - INFO [main] [AutomationRequestMatcher] Analyzing node nodeId... | |
| Jun 19, 2015 23:48:58:036 PM - INFO [main] [AutomationRequestMatcher] Node had 0 matching running sessions and 1 matching capable slots | |
| Jun 19, 2015 23:48:58:036 PM - INFO [main] [AutomationRequestMatcher] Node marked for termination. Subtracting 0 sessions from 0 total free slots | |
| Jun 19, 2015 23:48:58:036 PM - INFO [main] [AutomationRequestMatcher] Returning 0 free slots for request Run Request - Browser: firefox | |
| Jun 19, 2015 23:48:58:037 PM - INFO [main] [AutomationRequestMatcher] Analyzing node nodeId... | |
| Jun 19, 2015 23:48:58:038 PM - INFO [main] [AutomationRequestMatcher] Node had 0 matching running sessions and 0 matching capable slots | |
| Jun 19, 2015 23:48:58:038 PM - INFO [main] [AutomationRequestMatcher] Returning 0 free slots for request Run Request - Browser: firefox - OS: linux | |
| Jun 19, 2015 23:48:58:039 PM - INFO [main] [AutomationRequestMatcher] Analyzing node nodeId... | |
| Jun 19, 2015 23:48:58:040 PM - INFO [main] [AutomationRequestMatcher] Node had 0 matching running sessions and 10 matching capable slots | |
| Jun 19, 2015 23:48:58:040 PM - INFO [main] [AutomationRequestMatcher] Returning 10 free slots for request Run Request - Browser: firefox | |
| Jun 19, 2015 23:48:58:040 PM - INFO [main] [AutomationRequestMatcher] Analyzing node nodeId... | |
| Jun 19, 2015 23:48:58:041 PM - INFO [main] [AutomationRequestMatcher] Node had 0 matching running sessions and 0 matching capable slots | |
| Jun 19, 2015 23:48:58:041 PM - INFO [main] [AutomationRequestMatcher] Returning 0 free slots for request Run Request - Browser: firefox | |
| Jun 19, 2015 23:48:58:042 PM - INFO [main] [AutomationRequestMatcher] Analyzing node nodeId... | |
| Jun 19, 2015 23:48:58:042 PM - INFO [main] [AutomationRequestMatcher] Node had 0 matching running sessions and 10 matching capable slots | |
| Jun 19, 2015 23:48:58:043 PM - INFO [main] [AutomationRequestMatcher] Returning 10 free slots for request Run Request - Browser: firefox | |
| Jun 19, 2015 23:48:58:043 PM - INFO [main] [AutomationRequestMatcher] Analyzing node nodeId... | |
| Jun 19, 2015 23:48:58:044 PM - INFO [main] [AutomationRequestMatcher] Node had 0 matching running sessions and 10 matching capable slots | |
| Jun 19, 2015 23:48:58:044 PM - INFO [main] [AutomationRequestMatcher] Returning 10 free slots for request Run Request - Browser: firefox | |
| Jun 19, 2015 23:48:58:045 PM - INFO [main] [AutomationRequestMatcher] Analyzing node nodeId... | |
| Jun 19, 2015 23:48:58:045 PM - INFO [main] [AutomationRequestMatcher] Node had 0 matching running sessions and 10 matching capable slots | |
| Jun 19, 2015 23:48:58:046 PM - INFO [main] [AutomationRequestMatcher] Returning 5 free slots for request Run Request - Browser: firefox | |
| Jun 19, 2015 23:48:58:046 PM - INFO [main] [AutomationRequestMatcher] Analyzing node nodeId... | |
| Jun 19, 2015 23:48:58:047 PM - INFO [main] [AutomationRequestMatcher] Node had 0 matching running sessions and 0 matching capable slots | |
| Jun 19, 2015 23:48:58:047 PM - INFO [main] [AutomationRequestMatcher] Analyzing node nodeId... | |
| Jun 19, 2015 23:48:58:048 PM - INFO [main] [AutomationRequestMatcher] Node had 0 matching running sessions and 10 matching capable slots | |
| Jun 19, 2015 23:48:58:048 PM - WARN [main] [AutomationRequestMatcher] Requested run Run Request - Browser: chrome did not match pending run Run Request - UUID: runId - Thread count: 10 - Browser: firefox so count will not be included | |
| Jun 19, 2015 23:48:58:048 PM - INFO [main] [AutomationRequestMatcher] Returning 10 free slots for request Run Request - Browser: chrome | |
| Jun 19, 2015 23:48:58:049 PM - INFO [main] [AutomationRequestMatcher] Analyzing node nodeId... | |
| Jun 19, 2015 23:48:58:049 PM - INFO [main] [AutomationRequestMatcher] Node had 0 matching running sessions and 10 matching capable slots | |
| Jun 19, 2015 23:48:58:050 PM - INFO [main] [AutomationRequestMatcher] Returning 0 free slots for request Run Request - Browser: firefox | |
| Jun 19, 2015 11:48:58 PM org.openqa.grid.internal.TestSlot getNewSession | |
| INFO: Trying to create a new session on test slot {browserName=firefox, uuid=runId} | |
| Jun 19, 2015 23:48:58:051 PM - INFO [main] [AutomationRequestMatcher] Analyzing node nodeId... | |
| Jun 19, 2015 23:48:58:052 PM - INFO [main] [AutomationRequestMatcher] Node had 5 matching running sessions and 15 matching capable slots | |
| Jun 19, 2015 23:48:58:052 PM - INFO [main] [AutomationRequestMatcher] Returning 5 free slots for request Run Request - Browser: firefox | |
| Jun 19, 2015 11:48:58 PM org.openqa.grid.internal.TestSlot getNewSession | |
| INFO: Trying to create a new session on test slot {browserName=firefox, uuid=runId} | |
| Jun 19, 2015 23:48:58:054 PM - INFO [main] [AutomationRequestMatcher] Analyzing node nodeId... | |
| Jun 19, 2015 23:48:58:054 PM - INFO [main] [AutomationRequestMatcher] Node had 5 matching running sessions and 10 matching capable slots | |
| Jun 19, 2015 23:48:58:055 PM - INFO [main] [AutomationRequestMatcher] Returning 5 free slots for request Run Request - Browser: firefox | |
| Jun 19, 2015 23:48:58:056 PM - INFO [main] [AutomationRequestMatcher] Analyzing node nodeId... | |
| Jun 19, 2015 23:48:58:056 PM - INFO [main] [AutomationRequestMatcher] Node had 0 matching running sessions and 10 matching capable slots | |
| Jun 19, 2015 23:48:58:056 PM - INFO [main] [AutomationRequestMatcher] Returning 10 free slots for request Run Request - Browser: firefox | |
| Jun 19, 2015 11:48:58 PM org.openqa.grid.internal.TestSlot getNewSession | |
| INFO: Trying to create a new session on test slot {browserName=chrome} | |
| Jun 19, 2015 23:48:58:058 PM - INFO [main] [AutomationRequestMatcher] Analyzing node nodeId... | |
| Jun 19, 2015 23:48:58:059 PM - INFO [main] [AutomationRequestMatcher] Node had 0 matching running sessions and 5 matching capable slots | |
| Jun 19, 2015 23:48:58:059 PM - INFO [main] [AutomationRequestMatcher] Returning 5 free slots for request Run Request - Browser: firefox | |
| Jun 19, 2015 11:48:58 PM org.openqa.grid.internal.TestSlot getNewSession | |
| INFO: Trying to create a new session on test slot {browserName=chrome} | |
| Jun 19, 2015 23:48:58:062 PM - INFO [main] [AutomationRequestMatcher] Analyzing node nodeId... | |
| Jun 19, 2015 23:48:58:062 PM - INFO [main] [AutomationRequestMatcher] Node had 0 matching running sessions and 1 matching capable slots | |
| Jun 19, 2015 23:48:58:062 PM - WARN [main] [AutomationRequestMatcher] The number of free node slots was less than 0. Resetting to 0. | |
| Jun 19, 2015 23:48:58:063 PM - INFO [main] [AutomationRequestMatcher] Analyzing node nodeId... | |
| Jun 19, 2015 23:48:58:063 PM - INFO [main] [AutomationRequestMatcher] Node had 0 matching running sessions and 1 matching capable slots | |
| Jun 19, 2015 23:48:58:063 PM - INFO [main] [AutomationRequestMatcher] Returning 1 free slots for request Run Request - Browser: firefox | |
| Tests run: 17, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.026 sec | |
| Running com.rmn.qa.AutomationUtilsTest | |
| Tests run: 4, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.003 sec | |
| Running com.rmn.qa.servlet.AutomationTestRunServletTest | |
| Jun 19, 2015 23:48:58:087 PM - ERROR [main] [AutomationTestRunServlet] Parameter 'uuid' must be passed in as a query string parameter | |
| Jun 19, 2015 23:48:58:088 PM - ERROR [main] [AutomationTestRunServlet] Parameter 'browser' must be passed in as a query string parameter | |
| Jun 19, 2015 23:48:58:088 PM - ERROR [main] [AutomationTestRunServlet] Parameter 'threadCount' must be passed in as a query string parameter | |
| Jun 19, 2015 23:48:58:089 PM - INFO [main] [AutomationTestRunServlet] Server request received. Browser [firefox] - Requested Node Count [50] - Request UUID [testUuid] | |
| Jun 19, 2015 23:48:58:089 PM - INFO [main] [AutomationRunContext] Adding 50 tests for test run [runUUid] | |
| Jun 19, 2015 23:48:58:089 PM - INFO [main] [AutomationRunContext] Returning 0 free capacity for the hub | |
| Jun 19, 2015 23:48:58:089 PM - ERROR [main] [AutomationTestRunServlet] Requested node count of [50] could not be fulfilled due to hub limit. [0] nodes available - Request UUID [testUuid] | |
| Jun 19, 2015 23:48:58:090 PM - INFO [main] [AutomationTestRunServlet] Server request received. Browser [firefox] - Requested Node Count [50] - Request UUID [testUuid] | |
| Jun 19, 2015 23:48:58:090 PM - INFO [main] [AutomationRunContext] Adding 25 tests for test run [runUUid] | |
| Jun 19, 2015 23:48:58:090 PM - INFO [main] [AutomationRunContext] Returning 25 free capacity for the hub | |
| Jun 19, 2015 23:48:58:090 PM - ERROR [main] [AutomationTestRunServlet] Requested node count of [50] could not be fulfilled due to hub limit. [25] nodes available - Request UUID [testUuid] | |
| Jun 19, 2015 23:48:58:091 PM - INFO [main] [AutomationTestRunServlet] Server request received. Browser [firefox] - Requested Node Count [10] - Request UUID [testUuid] | |
| Jun 19, 2015 23:48:58:091 PM - INFO [main] [AutomationRunContext] Returning 50 free capacity for the hub | |
| Jun 19, 2015 23:48:58:091 PM - INFO [main] [AutomationTestRunServlet] Server request received. Browser [firefox] - Requested Node Count [10] - Request UUID [testUUid] | |
| Jun 19, 2015 23:48:58:091 PM - INFO [main] [AutomationRunContext] Returning 50 free capacity for the hub | |
| Jun 19, 2015 23:48:58:092 PM - INFO [main] [AutomationTestRunServlet] Server request received. Browser [firefox] - Requested Node Count [10] - Request UUID [testUUid] | |
| Jun 19, 2015 23:48:58:092 PM - INFO [main] [AutomationRunContext] Adding 10 tests for test run [testUUid] | |
| Jun 19, 2015 23:48:58:092 PM - INFO [main] [AutomationRunContext] Returning 40 free capacity for the hub | |
| Jun 19, 2015 23:48:58:092 PM - WARN [main] [AutomationTestRunServlet] Test run already exists for the same UUID [testUUid] | |
| Jun 19, 2015 23:48:58:093 PM - INFO [main] [AutomationTestRunServlet] Server request received. Browser [firefox] - Requested Node Count [6] - Request UUID [testUuid] | |
| Jun 19, 2015 23:48:58:093 PM - INFO [main] [AutomationRunContext] Returning 50 free capacity for the hub | |
| Jun 19, 2015 23:48:58:093 PM - WARN [main] [AutomationTestRunServlet] Insufficient nodes to fulfill request. New AMIs will be queued up. Requested [6] - Available [0] - Request UUID [testUuid] | |
| Jun 19, 2015 23:48:58:093 PM - INFO [main] [AutomationTestRunServlet] 6 threads requested | |
| Jun 19, 2015 23:48:58:094 PM - WARN [main] [AutomationTestRunServlet] Host name could not be determined from system property. | |
| Jun 19, 2015 23:48:58:094 PM - INFO [main] [AutomationTestRunServlet] 6 nodes will be started for run [testUuid] | |
| Jun 19, 2015 23:48:58:094 PM - INFO [main] [AutomationTestRunServlet] 1 instances started | |
| Jun 19, 2015 23:48:58:094 PM - INFO [main] [AutomationTestRunServlet] Node instance id: instanceId | |
| Jun 19, 2015 23:48:58:095 PM - INFO [main] [AutomationTestRunServlet] Server request received. Browser [chrome] - Requested Node Count [7] - Request UUID [testUuid] | |
| Jun 19, 2015 23:48:58:095 PM - INFO [main] [AutomationRunContext] Returning 50 free capacity for the hub | |
| Jun 19, 2015 23:48:58:095 PM - WARN [main] [AutomationTestRunServlet] Insufficient nodes to fulfill request. New AMIs will be queued up. Requested [7] - Available [0] - Request UUID [testUuid] | |
| Jun 19, 2015 23:48:58:095 PM - INFO [main] [AutomationTestRunServlet] 7 threads requested | |
| Jun 19, 2015 23:48:58:095 PM - WARN [main] [AutomationTestRunServlet] Host name could not be determined from system property. | |
| Jun 19, 2015 23:48:58:095 PM - INFO [main] [AutomationTestRunServlet] 2 nodes will be started for run [testUuid] | |
| Jun 19, 2015 23:48:58:096 PM - INFO [main] [AutomationTestRunServlet] 1 instances started | |
| Jun 19, 2015 23:48:58:096 PM - INFO [main] [AutomationTestRunServlet] Node instance id: instanceId | |
| Jun 19, 2015 23:48:58:096 PM - INFO [main] [AutomationTestRunServlet] Server request received. Browser [internetexplorer] - Requested Node Count [1] - Request UUID [testUuid] | |
| Jun 19, 2015 23:48:58:096 PM - INFO [main] [AutomationRunContext] Returning 50 free capacity for the hub | |
| Jun 19, 2015 23:48:58:097 PM - WARN [main] [AutomationTestRunServlet] Insufficient nodes to fulfill request. New AMIs will be queued up. Requested [1] - Available [0] - Request UUID [testUuid] | |
| Jun 19, 2015 23:48:58:097 PM - INFO [main] [AutomationTestRunServlet] 1 threads requested | |
| Jun 19, 2015 23:48:58:097 PM - INFO [main] [AutomationTestRunServlet] 1 nodes will be started for run [testUuid] | |
| Jun 19, 2015 23:48:58:097 PM - INFO [main] [AutomationTestRunServlet] 1 instances started | |
| Jun 19, 2015 23:48:58:097 PM - INFO [main] [AutomationTestRunServlet] Node instance id: instanceId | |
| Jun 19, 2015 23:48:58:098 PM - INFO [main] [AutomationTestRunServlet] Server request received. Browser [unknown] - Requested Node Count [7] - Request UUID [testUuid] | |
| Jun 19, 2015 23:48:58:098 PM - INFO [main] [AutomationRunContext] Returning 50 free capacity for the hub | |
| Jun 19, 2015 23:48:58:102 PM - INFO [main] [AutomationTestRunServlet] Instance ID detected. Hub termination thread will be started. | |
| Jun 19, 2015 23:48:58:103 PM - INFO [main] [AutomationTestRunServlet] Server request received. Browser [chrome] - Requested Node Count [7] - Request UUID [testUuid] | |
| Jun 19, 2015 23:48:58:104 PM - INFO [main] [AutomationRunContext] Returning 50 free capacity for the hub | |
| Jun 19, 2015 23:48:58:104 PM - WARN [main] [AutomationTestRunServlet] Insufficient nodes to fulfill request. New AMIs will be queued up. Requested [7] - Available [0] - Request UUID [testUuid] | |
| Jun 19, 2015 23:48:58:104 PM - INFO [main] [AutomationTestRunServlet] 7 threads requested | |
| Jun 19, 2015 23:48:58:104 PM - INFO [main] [AutomationTestRunServlet] 2 nodes will be started for run [testUuid] | |
| Jun 19, 2015 23:48:58:104 PM - INFO [main] [AutomationTestRunServlet] 1 instances started | |
| Jun 19, 2015 23:48:58:104 PM - INFO [main] [AutomationTestRunServlet] Node instance id: instanceId | |
| Jun 19, 2015 23:48:58:105 PM - INFO [main] [AutomationTestRunServlet] Instance ID detected. Hub termination thread will be started. | |
| Jun 19, 2015 23:48:58:106 PM - INFO [main] [AutomationTestRunServlet] Server request received. Browser [chrome] - Requested Node Count [7] - Request UUID [testUuid] | |
| Jun 19, 2015 23:48:58:106 PM - INFO [main] [AutomationRunContext] Returning 50 free capacity for the hub | |
| Jun 19, 2015 23:48:58:106 PM - WARN [main] [AutomationTestRunServlet] Insufficient nodes to fulfill request. New AMIs will be queued up. Requested [7] - Available [0] - Request UUID [testUuid] | |
| Jun 19, 2015 23:48:58:106 PM - INFO [main] [AutomationTestRunServlet] 7 threads requested | |
| Jun 19, 2015 23:48:58:106 PM - INFO [main] [AutomationTestRunServlet] 2 nodes will be started for run [testUuid] | |
| Jun 19, 2015 23:48:58:107 PM - INFO [main] [AutomationTestRunServlet] 1 instances started | |
| Jun 19, 2015 23:48:58:107 PM - INFO [main] [AutomationTestRunServlet] Node instance id: instanceId | |
| Jun 19, 2015 23:48:58:107 PM - INFO [main] [AutomationTestRunServlet] Server request received. Browser [firefox] - Requested Node Count [10] - Request UUID [testUuid] | |
| Jun 19, 2015 23:48:58:107 PM - INFO [main] [AutomationRunContext] Returning 50 free capacity for the hub | |
| Jun 19, 2015 23:48:58:108 PM - WARN [main] [AutomationTestRunServlet] Insufficient nodes to fulfill request. New AMIs will be queued up. Requested [10] - Available [0] - Request UUID [testUuid] | |
| Jun 19, 2015 23:48:58:108 PM - INFO [main] [AutomationTestRunServlet] 10 threads requested | |
| Jun 19, 2015 23:48:58:108 PM - INFO [main] [AutomationTestRunServlet] 10 nodes will be started for run [testUuid] | |
| Jun 19, 2015 23:48:58:108 PM - ERROR [main] [AutomationTestRunServlet] Error trying to start nodes: java.lang.RuntimeException: Can't start nodes | |
| Tests run: 14, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.038 sec | |
| Running com.rmn.qa.AutomationCapabilityMatcherTest | |
| Jun 19, 2015 23:48:58:113 PM - INFO [main] [AutomationCapabilityMatcher] Adding capability from property value: foo | |
| Jun 19, 2015 23:48:58:113 PM - INFO [main] [AutomationCapabilityMatcher] Adding capability: foo | |
| Jun 19, 2015 23:48:58:113 PM - INFO [main] [AutomationCapabilityMatcher] Adding capability: bar | |
| Jun 19, 2015 23:48:58:113 PM - INFO [main] [AutomationCapabilityMatcher] Adding capability from property value: foo | |
| Jun 19, 2015 23:48:58:118 PM - INFO [main] [AutomationCapabilityMatcher] Adding capability from property value: foo | |
| Jun 19, 2015 23:48:58:126 PM - INFO [main] [AutomationCapabilityMatcher] Adding capability from property value: foo | |
| Tests run: 9, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.015 sec | |
| Running com.rmn.qa.AutomationRunRequestTest | |
| Tests run: 17, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.009 sec | |
| Running com.rmn.qa.task.AutomationNodeRegistryTaskTest | |
| Jun 19, 2015 23:48:58:140 PM - INFO [main] [AutomationNodeRegistryTask] Looking for unregistered nodes | |
| Jun 19, 2015 23:48:58:141 PM - INFO [main] [AutomationNodeRegistryTask] Unregistered dynamic node found: Node - UUID: testUuid Instance ID: instanceId Created Date: Fri Jun 19 23:48:58 UTC 2015 | |
| Jun 19, 2015 23:48:58:141 PM - INFO [main] [AutomationNodeRegistryTask] Looking for unregistered nodes | |
| Jun 19, 2015 23:48:58:142 PM - INFO [main] [AutomationNodeRegistryTask] Looking for unregistered nodes | |
| Jun 19, 2015 23:48:58:142 PM - INFO [main] [AutomationNodeRegistryTask] Looking for unregistered nodes | |
| Jun 19, 2015 23:48:58:143 PM - INFO [main] [AutomationNodeRegistryTask] Looking for unregistered nodes | |
| Jun 19, 2015 23:48:58:144 PM - INFO [main] [AutomationNodeRegistryTask] Looking for unregistered nodes | |
| Jun 19, 2015 23:48:58:144 PM - ERROR [main] [AutomationNodeRegistryTask] Error trying to parse created date [06 23:48:58]: java.text.ParseException: Unparseable date: "06 23:48:58" | |
| Tests run: 7, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.003 sec | |
| Running com.rmn.qa.task.AutomationRunCleanupTaskTest | |
| Jun 19, 2015 23:48:58:145 PM - INFO [main] [AutomationRunContext] Tracked test run [uuid] found with no running tests. Adding to set for removal. | |
| Jun 19, 2015 23:48:58:145 PM - WARN [main] [AutomationRunContext] Removing run because it has no more running test slots. UUID [uuid] | |
| Jun 19, 2015 23:48:58:146 PM - INFO [main] [AutomationRunCleanupTask] Performing cleanup on runs. | |
| Jun 19, 2015 23:48:58:146 PM - WARN [main] [AutomationRunContext] No runs found to clean up | |
| Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0 sec | |
| Running com.rmn.qa.task.AutomationHubCleanupTaskTest | |
| Jun 19, 2015 23:48:58:149 PM - INFO [main] [AutomationHubCleanupTask] Performing cleanup on hub. | |
| Jun 19, 2015 23:48:58:149 PM - WARN [main] [AutomationHubCleanupTask] No running nodes found after hub expiration time -- terminating hub: dummyId | |
| Jun 19, 2015 23:48:58:150 PM - INFO [main] [AutomationHubCleanupTask] Performing cleanup on hub. | |
| Jun 19, 2015 23:48:58:150 PM - ERROR [main] [AutomationHubCleanupTask] Error parsing created date for hub: java.text.ParseException: Unparseable date: "Mon Feb 17 20:56:48 UTC 2014" | |
| Jun 19, 2015 23:48:58:150 PM - INFO [main] [AutomationHubCleanupTask] Error was encountered parsing the created date, so the hub will be shutdown as it is empty. | |
| Jun 19, 2015 23:48:58:151 PM - INFO [main] [AutomationHubCleanupTask] Performing cleanup on hub. | |
| Jun 19, 2015 23:48:58:151 PM - INFO [main] [AutomationHubCleanupTask] Hub could not be shutdown yet. | |
| Jun 19, 2015 23:48:58:152 PM - INFO [main] [AutomationHubCleanupTask] Performing cleanup on hub. | |
| Jun 19, 2015 23:48:58:152 PM - INFO [main] [AutomationHubCleanupTask] Current date: Fri Jun 19 23:48:58 UTC 2015 | |
| Jun 19, 2015 23:48:58:152 PM - INFO [main] [AutomationHubCleanupTask] Current end date: Fri Jun 19 23:42:58 UTC 2015 | |
| Jun 19, 2015 23:48:58:153 PM - INFO [main] [AutomationHubCleanupTask] Hub [dummyId] ran into the next billing cycle. Increasing end date. | |
| Tests run: 6, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.004 sec | |
| Running com.rmn.qa.task.AutomationReaperTaskTest | |
| Jun 19, 2015 23:48:58:155 PM - INFO [main] [AutomationReaperTask] Running VM Reaper Task | |
| Jun 19, 2015 23:48:58:156 PM - INFO [main] [AutomationReaperTask] Running VM Reaper Task | |
| Jun 19, 2015 23:48:58:157 PM - INFO [main] [AutomationReaperTask] Running VM Reaper Task | |
| Tests run: 4, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 0.002 sec <<< FAILURE! | |
| Running com.rmn.qa.task.AutomationNodeCleanupTaskTest | |
| Jun 19, 2015 23:48:58:163 PM - INFO [main] [AutomationNodeCleanupTask] Performing cleanup on nodes. | |
| Jun 19, 2015 23:48:58:164 PM - INFO [main] [AutomationNodeCleanupTask] Performing cleanup on nodes. | |
| Jun 19, 2015 23:48:58:164 PM - ERROR [main] [AutomationNodeCleanupTask] No browsers found for node: dummyId | |
| Jun 19, 2015 23:48:58:164 PM - INFO [main] [AutomationNodeCleanupTask] Updating node dummyId to 'EXPIRED' status. Start date [Fri Jun 19 22:52:58 UTC 2015] End date [Fri Jun 19 23:47:58 UTC 2015] | |
| Jun 19, 2015 11:48:58 PM org.openqa.grid.internal.TestSlot getNewSession | |
| INFO: Trying to create a new session on test slot {browserName=firefox} | |
| Jun 19, 2015 23:48:58:165 PM - INFO [main] [AutomationNodeCleanupTask] Performing cleanup on nodes. | |
| Jun 19, 2015 23:48:58:166 PM - INFO [main] [AutomationNodeCleanupTask] 5 matching slots were found for node dummyId | |
| Jun 19, 2015 23:48:58:166 PM - INFO [main] [AutomationNodeCleanupTask] Current load will not allow for node to shutdown right now. Node: dummyId Request: Run Request - Browser: firefox Free Slots: 4 Node Slots: 5 | |
| Jun 19, 2015 11:48:58 PM org.openqa.grid.internal.TestSlot getNewSession | |
| INFO: Trying to create a new session on test slot {browserName=firefox} | |
| Jun 19, 2015 23:48:58:167 PM - INFO [main] [AutomationNodeCleanupTask] Performing cleanup on nodes. | |
| Jun 19, 2015 23:48:58:168 PM - INFO [main] [AutomationNodeCleanupTask] 5 matching slots were found for node dummyId | |
| Jun 19, 2015 23:48:58:168 PM - INFO [main] [AutomationNodeCleanupTask] Current load will not allow for node to shutdown right now. Node: dummyId Request: Run Request - Browser: firefox Free Slots: 4 Node Slots: 5 | |
| Jun 19, 2015 23:48:58:168 PM - INFO [main] [AutomationNodeCleanupTask] Performing cleanup on nodes. | |
| Jun 19, 2015 23:48:58:169 PM - WARN [main] [AutomationNodeCleanupTask] Node dummyId cannot be shutdown yet as a new run is queued up. | |
| Jun 19, 2015 23:48:58:169 PM - INFO [main] [AutomationNodeCleanupTask] Performing cleanup on nodes. | |
| Jun 19, 2015 23:48:58:169 PM - ERROR [main] [AutomationNodeCleanupTask] No browsers found for node: dummyId | |
| Jun 19, 2015 23:48:58:169 PM - INFO [main] [AutomationNodeCleanupTask] Updating node dummyId to 'EXPIRED' status. Start date [Fri Jun 19 22:52:58 UTC 2015] End date [Fri Jun 19 23:47:58 UTC 2015] | |
| Jun 19, 2015 23:48:58:170 PM - INFO [main] [AutomationNodeCleanupTask] Performing cleanup on nodes. | |
| Jun 19, 2015 23:48:58:170 PM - WARN [main] [AutomationNodeCleanupTask] No matching node was found in the proxy set. Instance id: dummyId | |
| Jun 19, 2015 23:48:58:170 PM - INFO [main] [AutomationNodeCleanupTask] Terminating node dummyId and updating status to 'TERMINATED' | |
| Jun 19, 2015 11:48:58 PM org.openqa.grid.internal.TestSlot getNewSession | |
| INFO: Trying to create a new session on test slot {browserName=firefox} | |
| Jun 19, 2015 23:48:58:171 PM - INFO [main] [AutomationNodeCleanupTask] Performing cleanup on nodes. | |
| Jun 19, 2015 23:48:58:171 PM - INFO [main] [AutomationNodeCleanupTask] 5 matching slots were found for node nodeId | |
| Jun 19, 2015 23:48:58:171 PM - INFO [main] [AutomationNodeCleanupTask] Load suitable for Request [Run Request - Browser: firefox]. Free slots [10] Node slots [5] | |
| Jun 19, 2015 23:48:58:172 PM - INFO [main] [AutomationNodeCleanupTask] Updating node nodeId to 'EXPIRED' status. Start date [Fri Jun 19 22:52:58 UTC 2015] End date [Fri Jun 19 23:47:58 UTC 2015] | |
| Jun 19, 2015 23:48:58:172 PM - INFO [main] [AutomationNodeCleanupTask] Performing cleanup on nodes. | |
| Jun 19, 2015 23:48:58:172 PM - INFO [main] [AutomationNodeCleanupTask] Performing cleanup on nodes. | |
| Jun 19, 2015 23:48:58:172 PM - ERROR [main] [AutomationNodeCleanupTask] No browsers found for node: dummyId | |
| Jun 19, 2015 23:48:58:173 PM - INFO [main] [AutomationNodeCleanupTask] Updating node dummyId to 'EXPIRED' status. Start date [Fri Jun 19 22:52:58 UTC 2015] End date [Fri Jun 19 23:47:58 UTC 2015] | |
| Jun 19, 2015 23:48:58:173 PM - INFO [main] [AutomationNodeCleanupTask] Performing cleanup on nodes. | |
| Jun 19, 2015 23:48:58:173 PM - INFO [main] [AutomationNodeCleanupTask] Node [dummyId] was still running after initial allotted time. Resetting status and increasing end date to Fri Jun 19 23:47:58 UTC 2015. | |
| Jun 19, 2015 11:48:58 PM org.openqa.grid.internal.TestSlot getNewSession | |
| INFO: Trying to create a new session on test slot {browserName=firefox} | |
| Jun 19, 2015 11:48:58 PM org.openqa.grid.internal.TestSlot getNewSession | |
| INFO: Trying to create a new session on test slot {browserName=firefox} | |
| Jun 19, 2015 11:48:58 PM org.openqa.grid.internal.TestSlot getNewSession | |
| INFO: Trying to create a new session on test slot {browserName=firefox} | |
| Jun 19, 2015 23:48:58:175 PM - INFO [main] [AutomationNodeCleanupTask] Performing cleanup on nodes. | |
| Jun 19, 2015 23:48:58:175 PM - INFO [main] [AutomationRequestMatcher] Analyzing node dummyId... | |
| Jun 19, 2015 23:48:58:176 PM - INFO [main] [AutomationRequestMatcher] Node had 2 matching running sessions and 4 matching capable slots | |
| Jun 19, 2015 23:48:58:176 PM - INFO [main] [AutomationRequestMatcher] Analyzing node dummyId2... | |
| Jun 19, 2015 23:48:58:176 PM - INFO [main] [AutomationRequestMatcher] Node had 2 matching running sessions and 4 matching capable slots | |
| Jun 19, 2015 23:48:58:176 PM - INFO [main] [AutomationRequestMatcher] Analyzing node dummyId3... | |
| Jun 19, 2015 23:48:58:176 PM - INFO [main] [AutomationRequestMatcher] Node had 2 matching running sessions and 4 matching capable slots | |
| Jun 19, 2015 23:48:58:177 PM - INFO [main] [AutomationRequestMatcher] Returning 6 free slots for request Run Request - Browser: firefox | |
| Jun 19, 2015 23:48:58:177 PM - INFO [main] [AutomationNodeCleanupTask] 4 matching slots were found for node dummyId2 | |
| Jun 19, 2015 23:48:58:177 PM - INFO [main] [AutomationNodeCleanupTask] Load suitable for Request [Run Request - Browser: firefox]. Free slots [6] Node slots [4] | |
| Jun 19, 2015 23:48:58:177 PM - INFO [main] [AutomationNodeCleanupTask] Updating node dummyId2 to 'EXPIRED' status. Start date [Fri Jun 19 22:52:58 UTC 2015] End date [Fri Jun 19 23:47:58 UTC 2015] | |
| Jun 19, 2015 23:48:58:177 PM - INFO [main] [AutomationRequestMatcher] Analyzing node dummyId... | |
| Jun 19, 2015 23:48:58:177 PM - INFO [main] [AutomationRequestMatcher] Node had 2 matching running sessions and 4 matching capable slots | |
| Jun 19, 2015 23:48:58:178 PM - INFO [main] [AutomationRequestMatcher] Analyzing node dummyId2... | |
| Jun 19, 2015 23:48:58:178 PM - INFO [main] [AutomationRequestMatcher] Node had 2 matching running sessions and 4 matching capable slots | |
| Jun 19, 2015 23:48:58:178 PM - INFO [main] [AutomationRequestMatcher] Node marked for termination. Subtracting 2 sessions from 2 total free slots | |
| Jun 19, 2015 23:48:58:178 PM - INFO [main] [AutomationRequestMatcher] Analyzing node dummyId3... | |
| Jun 19, 2015 23:48:58:178 PM - INFO [main] [AutomationRequestMatcher] Node had 2 matching running sessions and 4 matching capable slots | |
| Jun 19, 2015 23:48:58:179 PM - INFO [main] [AutomationRequestMatcher] Returning 2 free slots for request Run Request - Browser: firefox | |
| Jun 19, 2015 23:48:58:179 PM - INFO [main] [AutomationNodeCleanupTask] 4 matching slots were found for node dummyId3 | |
| Jun 19, 2015 23:48:58:179 PM - INFO [main] [AutomationNodeCleanupTask] Current load will not allow for node to shutdown right now. Node: dummyId3 Request: Run Request - Browser: firefox Free Slots: 2 Node Slots: 4 | |
| Jun 19, 2015 23:48:58:179 PM - INFO [main] [AutomationRequestMatcher] Analyzing node dummyId... | |
| Jun 19, 2015 23:48:58:179 PM - INFO [main] [AutomationRequestMatcher] Node had 2 matching running sessions and 4 matching capable slots | |
| Jun 19, 2015 23:48:58:180 PM - INFO [main] [AutomationRequestMatcher] Analyzing node dummyId2... | |
| Jun 19, 2015 23:48:58:180 PM - INFO [main] [AutomationRequestMatcher] Node had 2 matching running sessions and 4 matching capable slots | |
| Jun 19, 2015 23:48:58:180 PM - INFO [main] [AutomationRequestMatcher] Node marked for termination. Subtracting 2 sessions from 2 total free slots | |
| Jun 19, 2015 23:48:58:180 PM - INFO [main] [AutomationRequestMatcher] Analyzing node dummyId3... | |
| Jun 19, 2015 23:48:58:180 PM - INFO [main] [AutomationRequestMatcher] Node had 2 matching running sessions and 4 matching capable slots | |
| Jun 19, 2015 23:48:58:181 PM - INFO [main] [AutomationRequestMatcher] Returning 2 free slots for request Run Request - Browser: firefox | |
| Jun 19, 2015 23:48:58:181 PM - INFO [main] [AutomationNodeCleanupTask] 4 matching slots were found for node dummyId | |
| Jun 19, 2015 23:48:58:181 PM - INFO [main] [AutomationNodeCleanupTask] Current load will not allow for node to shutdown right now. Node: dummyId Request: Run Request - Browser: firefox Free Slots: 2 Node Slots: 4 | |
| Jun 19, 2015 23:48:58:181 PM - INFO [main] [AutomationNodeCleanupTask] Performing cleanup on nodes. | |
| Jun 19, 2015 23:48:58:182 PM - ERROR [main] [AutomationNodeCleanupTask] No browsers found for node: dummyId | |
| Jun 19, 2015 23:48:58:182 PM - INFO [main] [AutomationNodeCleanupTask] Updating node dummyId to 'EXPIRED' status. Start date [Fri Jun 19 22:52:58 UTC 2015] End date [Fri Jun 19 23:47:58 UTC 2015] | |
| Jun 19, 2015 23:48:58:182 PM - INFO [main] [AutomationNodeCleanupTask] Performing cleanup on nodes. | |
| Jun 19, 2015 23:48:58:182 PM - WARN [main] [AutomationNodeCleanupTask] No matching node was found in the proxy set. Instance id: dummyId | |
| Jun 19, 2015 23:48:58:182 PM - INFO [main] [AutomationNodeCleanupTask] Terminating node dummyId and updating status to 'TERMINATED' | |
| Jun 19, 2015 23:48:58:182 PM - INFO [main] [AutomationNodeCleanupTask] Performing cleanup on nodes. | |
| Jun 19, 2015 23:48:58:182 PM - INFO [main] [AutomationNodeCleanupTask] Removing node [dummyId] from internal tracking set | |
| Tests run: 11, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.016 sec | |
| Running com.rmn.qa.AbstractAutomationCleanupTaskTest | |
| Jun 19, 2015 23:48:58:184 PM - ERROR [main] [AbstractAutomationCleanupTask] Error executing cleanup thread [null]: java.lang.RuntimeException: test exception | |
| java.lang.RuntimeException: test exception | |
| at com.rmn.qa.AbstractAutomationCleanupTaskTest$TestTask.<init>(AbstractAutomationCleanupTaskTest.java:33) ~[test-classes/:na] | |
| at com.rmn.qa.AbstractAutomationCleanupTaskTest.testExceptionHandled(AbstractAutomationCleanupTaskTest.java:26) ~[test-classes/:na] | |
| at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_79] | |
| at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_79] | |
| at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_79] | |
| at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_79] | |
| at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44) [junit-4.8.1.jar:na] | |
| at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15) [junit-4.8.1.jar:na] | |
| at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41) [junit-4.8.1.jar:na] | |
| at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20) [junit-4.8.1.jar:na] | |
| at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76) [junit-4.8.1.jar:na] | |
| at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50) [junit-4.8.1.jar:na] | |
| at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193) [junit-4.8.1.jar:na] | |
| at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52) [junit-4.8.1.jar:na] | |
| at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191) [junit-4.8.1.jar:na] | |
| at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42) [junit-4.8.1.jar:na] | |
| at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184) [junit-4.8.1.jar:na] | |
| at org.junit.runners.ParentRunner.run(ParentRunner.java:236) [junit-4.8.1.jar:na] | |
| at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:236) [surefire-junit4-2.12.jar:2.12] | |
| at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:134) [surefire-junit4-2.12.jar:2.12] | |
| at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:113) [surefire-junit4-2.12.jar:2.12] | |
| at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_79] | |
| at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_79] | |
| at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_79] | |
| at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_79] | |
| at org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:189) [surefire-api-2.12.jar:2.12] | |
| at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:165) [surefire-booter-2.12.jar:2.12] | |
| at org.apache.maven.surefire.booter.ProviderFactory.invokeProvider(ProviderFactory.java:85) [surefire-booter-2.12.jar:2.12] | |
| at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:103) [surefire-booter-2.12.jar:2.12] | |
| at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:74) [surefire-booter-2.12.jar:2.12] | |
| Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.001 sec | |
| Running com.rmn.qa.AutomationDynamicNodeTest | |
| Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.056 sec | |
| Results : | |
| Failed tests: testShutdown(com.rmn.qa.task.AutomationReaperTaskTest): Node should be terminated as it was empty | |
| Tests run: 137, Failures: 1, Errors: 0, Skipped: 0 | |
| [INFO] ------------------------------------------------------------------------ | |
| [INFO] BUILD FAILURE | |
| [INFO] ------------------------------------------------------------------------ | |
| [INFO] Total time: 7.592 s | |
| [INFO] Finished at: 2015-06-19T23:48:58+00:00 | |
| [INFO] Final Memory: 27M/309M | |
| [INFO] ------------------------------------------------------------------------ | |
| [ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:2.12:test (default-test) on project selenium-grid-scaler: There are test failures. | |
| [ERROR] | |
| [ERROR] Please refer to /home/ec2-user/SeleniumGridScaler/target/surefire-reports for the individual test results. | |
| [ERROR] -> [Help 1] | |
| [ERROR] | |
| [ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch. | |
| [ERROR] Re-run Maven using the -X switch to enable full debug logging. | |
| [ERROR] | |
| [ERROR] For more information about the errors and possible solutions, please read the following articles: | |
| [ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoFailureException |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment