Bisect the dragon
It all started on Friday, like many of the bad things that can happen in software ;) We’ve been working for some time and after being blocked with deployments for a long time (don’t ask, you don’t want to know ;)) we were finally able to deploy a new version. Our last release was about week ago. Do the deployment - seems like the easy thing to do. I’ve triggered deploy plan on Jenkins and it’s failed. Here is the story how I’ve fixed something that looked like hours of analysis in few minutes.
Long story short, as a part of deployment process the new version is set by Jenkins and it failed. The output of the build ended with something like this:
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 1.926 s
[INFO] Finished at: 2017-12-10T20:47:05+01:00
[INFO] Final Memory: 15M/188M
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.codehaus.mojo:versions-maven-plugin:2.3:set (default-cli) on
project bisect-the-dragon: Execution default-cli of goal
org.codehaus.mojo:versions-maven-plugin:2.3:set failed.: EmptyStackException -> [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/PluginExecutionExceptionRunning with debug (-X) wasn’t helpful at all. I went through all 5 stages of bug fixing process:
Denial - I’ve run the build 2 more times just to be sure ;)
Anger - wtf is going on?
Bargaining - maybe Jenkins is broken I’ll run this locally just to be sure
Depression - why it is happening to me on Friday?
Challenge accepted - I’m going to find the problem and fix it
Let’s skip to the last phase because it was the most productive one…
I’ve started by investigating git log. A lot of changes… So maybe I’ll find changes in pom.xml files only. Still, more then I’d want to review manually and the team is waiting for the deployment. Luckily I’ve decided not to figure this out with an empty stomach. During lunch I’ve recalled "exotic" command - git bisect. After checking out google for information how to use it I was ready for next round. Using git bisect I was able to find the problem in a matter of few minutes…
For educational purposes, I’ve created the very simple project which simulates the process.
Before we start we’ll need two commits. First is the bad one - usually top of the HEAD. Second is good one, for me, it was the last release
pawel@tet:~/Workspace/blog-examples/bisect-the-dragon$ git log
a4cb0c8 Pawel Chudzik 3 seconds ago : added cleanup script
c87de46 Pawel Chudzik 21 hours ago : cleanup
6d2df59 Pawel Chudzik 21 hours ago : added readme.md
e7072fa Pawel Chudzik 21 hours ago : fixed project setup with separete corporate poms
6132330 Pawel Chudzik 9 days ago : added diff file
96ae05b Pawel Chudzik 9 days ago : set compiler plugin version
9aaffa5 Pawel Chudzik 9 days ago : add assertj
443afc9 Pawel Chudzik 9 days ago : run tests alphabetical
bb86569 Pawel Chudzik 9 days ago : bumped corporate pom version
85c13b6 Pawel Chudzik 9 days ago : added support for java 8
2bfd094 Pawel Chudzik 9 days ago : increased memory for tests
7020b21 Pawel Chudzik 9 days ago : added corporate pom
31c1fc6 Pawel Chudzik 9 days ago : added tests
2971dca Pawel Chudzik 9 days ago : added code
6fd3a3d Pawel Chudzik 9 days ago : initial commit
pawel@tet:~/Workspace/blog-examples/bisect-the-dragon$ git bisect start
pawel@tet:~/Workspace/blog-examples/bisect-the-dragon$ git bisect bad
pawel@tet:~/Workspace/blog-examples/bisect-the-dragon$ git bisect good 6fd3a3d
Bisecting: 6 revisions left to test after this (roughly 3 steps)
[443afc9780758bcbed101e252a4968ad28d9f202] run tests alphabetical
pawel@tet:~/Workspace/blog-examples/bisect-the-dragon$Now we can start the hard work ;)
pawel@tet:~/Workspace/blog-examples/bisect-the-dragon$ (cd project/ && mvn -q versions:set -DnewVersion=1.0.0)
[ERROR] Failed to execute goal org.codehaus.mojo:versions-maven-plugin:2.3:set (default-cli) on
project bisect-the-dragon: Execution default-cli of goal
org.codehaus.mojo:versions-maven-plugin:2.3:set failed.: EmptyStackException -> [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/PluginExecutionExceptionOk it has failed let’s tell git about it:
pawel@tet:~/Workspace/blog-examples/bisect-the-dragon$ g bisect bad
Bisecting: 3 revisions left to test after this (roughly 2 steps)
[7020b21674e20b4352b10708d553c21dcbaf1bcc] added corporate pomLet’s check again:
pawel@tet:~/Workspace/blog-examples/bisect-the-dragon$ (cd project/ && mvn -q versions:set -DnewVersion=1.0.0)It is ok. Let’s clean up and let git know that it is working now:
pawel@tet:~/Workspace/blog-examples/bisect-the-dragon$ git clean -f && git checkout -- .
Removing project/pom.xml.versionsBackup
pawel@tet:~/Workspace/blog-examples/bisect-the-dragon$ git bisect good
Bisecting: 1 revision left to test after this (roughly 1 step)
[85c13b67b5f41a0beb42c8d44040739497b6584b] added support for java 8Now all I have to do is to run the procedure unit git will tell us which commit caused the problem.
pawel@tet:~/Workspace/blog-examples/bisect-the-dragon$ (cd project/ && mvn -q versions:set -DnewVersion=1.0.0)
[ERROR] Failed to execute goal org.codehaus.mojo:versions-maven-plugin:2.3:set (default-cli) on
project bisect-the-dragon: Execution default-cli of goal
org.codehaus.mojo:versions-maven-plugin:2.3:set failed.: EmptyStackException -> [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/PluginExecutionException
pawel@tet:~/Workspace/blog-examples/bisect-the-dragon$ git bisect bad
Bisecting: 0 revisions left to test after this (roughly 0 steps)
[2bfd094fa8609d3451d0bc3ad1d73b933ca781fa] increased memory for tests
pawel@tet:~/Workspace/blog-examples/bisect-the-dragon$ (cd project/ && mvn -q versions:set -DnewVersion=1.0.0)
[ERROR] Failed to execute goal org.codehaus.mojo:versions-maven-plugin:2.3:set (default-cli) on
project bisect-the-dragon: Execution default-cli of goal
org.codehaus.mojo:versions-maven-plugin:2.3:set failed.: EmptyStackException -> [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/PluginExecutionException
pawel@tet:~/Workspace/blog-examples/bisect-the-dragon$ git bisect bad
2bfd094fa8609d3451d0bc3ad1d73b933ca781fa is the first bad commit
commit 2bfd094fa8609d3451d0bc3ad1d73b933ca781fa
Author: Pawel Chudzik <pawel.chudzik@gmail.com>
Date: Sun Dec 10 20:28:23 2017 +0100
increased memory for tests
:040000 040000 a17896b12538fb24faeda856cc384250f5a08865 b76a330e3e358b1814cfee11d3355aecbc7da10c M projectUps that’s on me :P let’s investigate the commit (note that git printed hashes of commits to compare):
pawel@tet:~/Workspace/blog-examples/bisect-the-dragon$ git diff a17896b12538fb24faeda856cc384250f5a08865 b76a330e3e358b1814cfee11d3355aecbc7da10c
diff --git a/pom.xml b/pom.xml
index d12fc44..2d09e6c 100644
--- a/pom.xml
+++ b/pom.xml
@@ -26,4 +26,21 @@
<scope>test</scope>
</dependency>
</dependencies>
+
+ <build>
+ <plugins>
+ <plugin>
+ <groupId>org.apache.maven.plugins</groupId>
+ <artifactId>maven-surefire-plugin</artifactId>
+ <version>2.20.1</version>
+ <configuration>
+ <systemPropertyVariables>
+ <mysql.workdir:data>/tmp/mysql/data</mysql.workdir:data>
+ <mysql.workdir:logs>/tmp/mysql/logs</mysql.workdir:logs>
+ </systemPropertyVariables>
+ <argLine>-Xmx256m</argLine>
+ </configuration>
+ </plugin>
+ </plugins>
+ </build>
</project>
Ok nothing interesting at first glance, but those systemPropertyVariables looks fishy, why do I need to configure MySQL for tests? Turn’s out that colon is a forbidden character in this context. Pretty lame problem, but it has passed all previous (up to install) phases but version setting…
After finding out broken commit I’ve decided to read the manual of git bisect and found out that I could’ve automated the whole process:
pawel@tet:~/Workspace/blog-examples/bisect-the-dragon$ git bisect start
pawel@tet:~/Workspace/blog-examples/bisect-the-dragon$ git bisect bad
pawel@tet:~/Workspace/blog-examples/bisect-the-dragon$ git bisect good 6fd3a3d
Bisecting: 6 revisions left to test after this (roughly 3 steps)
[443afc9780758bcbed101e252a4968ad28d9f202] run tests alphabetical
pawel@tet:~/Workspace/blog-examples/bisect-the-dragon$ git bisect run sh -c "(cd project && mvn versions:set -DgenerateBackupPoms=false -DnewVersion=1.0.0 && git checkout -- .)"This will automatically run the whole bug tracking process and pinpoint broken commit automatically. With this knowledge, I’ll be able to work smarter not harder in the future :)
My example was lame and because of that I came up with the git bisect solution but now I see a lot of potential in this tool and I’m pretty sure it will save me some more time in the future.
Source code can be found on my github
If you’ve never used git bisect I encourage you to run the samples on your own:
git clone https://github.com/pchudzik/blog-example-bisect-dragon.git
cd blog-example-bisect-dragon
(cd corporate && mvn -f pom-v1.xml install && mvn -f pom-v2.xml install) # or run ./setup.sh
git bisect start
git bisect bad
git bisect good 6fd3a3d
git bisect run sh -c "(cd project && mvn versions:set -DgenerateBackupPoms=false -DnewVersion=1.0.0 && git checkout -- .)"
rm -rf $HOME/.m2/repository/com/pchudzik/blog/example/corporate-dragon # or run ./cleanup.shIf you've enjoyed or found this post useful you might also like:
21 Dec 2017 #howto #interesting #git