Forem: Andrey Cheboksarov

Reverse engineer Spring Web in 5 minutes using a recording debugger

Andrey Cheboksarov — Wed, 18 Dec 2024 07:16:48 +0000

Large Java frameworks can be reverse engineered with help of some tools. The article shows how to dig into Spring Web internals with help of ulyp in less than 10 minutes. A developer can observe how framework works inside before diving into source code. This is a part 2 of the ongoing blog series about ulyp. The first part is available here.

Introduction

When working with gigantic frameworks, the main issue is to analyze their codebase. Sometimes, a developer needs to get understanding of internals real quick. This can happen when something doesn't work as expected, yet basic debugging doesn't help much.

Some of the ways to get into the codebase:

Use plain old debugger. Stop the app at some breakpoint and check the stack trace and surrounding types.
Dive right to the source code with the obtained knowledge.
Start from tests. Tests can be quite helpful if one wants to understand the codebase.
Enable TRACE logs and try to gather some info from them.
Use a sampling profiler. Building a flamegraph could be quite a good idea to start from. This can be quite useful if the app being analyzed is already under load.
Use a recording debugger, which records the whole execution flow and then can show the call tree.

The article focuses on the last approach. In certain cases, using such a tool might be useful for a anybody who works with large codebase. Recorded execution flow can be used to get the idea how things work at runtime. A developer can then dive into source code with good understanding.

Reverse engineering Spring Web

We will see how the tool works on Spring Web based app. The project which we are going to
use is spring-petclinic. This is a basic web app written on Java with Spring Web.
Suppose, we want to understand how it works. And we want to do it really quick.

We will skip the setup and jump right to recording. The first thing we want to know is where to start recording. This can be done by plenty of ways, but the easiest way is to gather some stack traces. If we stop inside the controller we see the top of the stacktrace is

    <app methods>
    ...
    <other spring methods>
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
    ...
    <tomcat methods>
    at java.base/java.lang.Thread.run(Thread.java:1583)

Since we want to reverse engineer Spring Web, we'd like to start from the bottom of the stacktrace. This is org.springframework.web.filter.OncePerRequestFilter
in our case. It's a first called method of Spring framework.

If we want to record execution, we should configure ulyp first. We specify the following system properties when start petclinic app,
no code change is required.

-javaagent:/home/tools/ulyp/ulyp-agent-1.0.2.jar
-Dulyp.methods=**.OncePerRequestFilter.doFilter
-Dulyp.file=/tmp/test-petclinic.dat
-Dulyp.record-constructors
-Dulyp.record-collections=JDK
-Dulyp.record-arrays

Specifying -Dulyp.methods=**.OncePerRequestFilter.doFilter makes ulyp start recording whenever doFilter method of any class named OncePerRequestFilter is called. -Dulyp.file=/tmp/test-petclinic.dat specifies the output filepath. The other props enable additional recording features which is optional.

We open the UI at url http://localhost:4200/petclinic/vets which lists all veterinarians. We stop the app after, since ulyp
writes everything to the output file immediately.

Now, we want to see what's recorded. ulyp comes with the desktop app which can open recording files. If we open /tmp/test-petclinic.dat file, we can observe there is indeed some recorded data.

What we see is a recording call tree. The top method is OncePerRequestFilter.doFilter as we expected. The next level are
methods which were called inside the method call (basically, children). Black background line hints how many calls are inside every subtree.
We can unfold every method call which has nested calls recorded. If we unfold further down, we can get the overall idea.
Spring Web implements chain of responsibility pattern. So,
every filter does some work and then calls the next filter. Here we see that OrderedFormContentFilter calls
OrderedRequestContextFilter.

You can read more about Servlet based application architecture here.

If we dig down, we can observe how Spring Web creates micrometer events.
Other stuff is updating context which can be accessed from other filters.

There are also many filters which are called on the path. The next interesting one is AuthorizationFilter. We can
see how it calls ObservationAuthorizationManager.check method, which returns an instance of AuthorizationDecision.
The filter later checks that AuthorizationDecision.isGranted returns true, which means the user has the access.

Next, we can see how DispatcherServlet.doDispatch is called, which does some logic, and finally we see our controller is called.
The VetController returned a list of Vet objects.

Basically, we can check how Spring MVC works, calls filters, validators, maps response into json, etc.
Every method is recorded which later can be analyzed.

If we wanted it, we could dig down to Hibernate or even JDBC level, but that's not the point of the article. The first part of the blog series shows how ulyp records Hibernate internals.

Conclusion

The article shown how a developer can record and analyze the internals of large framework. The obtained knowledge can
help in development. Feel free to try ulyp while working on a huge codebase.

Ulyp: Recording Java code execution for faster debugging (Part 1)

Andrey Cheboksarov — Sun, 13 Oct 2024 06:41:30 +0000

This is the first part of a 10-post series describing the background and motivation behind Ulyp.

Introduction

The article presents Ulyp which is an open-source instrumentation agent that records method calls (including argument and return values) of all third-party libraries of JVM apps. Software engineer can later upload a recording file to the UI desktop app in order to better understand the internals of libraries and even the whole applications. The tool can help developers understand the internals of frameworks faster, gain deeper insights, find inefficiencies in software, as well as debug more effectively.
In a few words, Ulyp converts this:

LoadingCache<Integer, DatabaseEntity> cache = Caffeine.newBuilder()
    ...
    .build(databaseSource::findById);

DatabaseEntity fromCache = cache.get(5);

to this:

Challenges in Modern Software engineering

The software engineering field nowadays is completely different from what it was 10 years ago. As scale of IT solutions rises, the complexity of systems is now is on entirely different level. A typical application may have thousands of instances in multiple availability zones. At the same time, the amount of code is usually around hundreds thousands lines.

The number of frameworks and libraries used as a dependency in a typical app is also higher than it was before. When it comes to gigantic frameworks which require tons of boilerplate, Java language is somewhat notorious. The ecosystem carries the largest frameworks ever created. Some examples are Spring, Hibernate and others.

One of the problem a modern Java developer faces is understanding code quickly. An average engineer spends way more time reading code than writing it. Understanding how libraries and frameworks work under the hood and what they do is extremely vital for proper software development.

Another problem is debugging a running instance of an application on some environment where classic debugger might not be available. Usually, it’s possible to use logs and APM tracers, but these tools might not always suffice the needs.

One possible way to mitigate some of these problems is code execution recording for later analysis. The idea is by far not new as there are already dozens of time-travel debuggers for different languages.

Introducing Ulyp: A recording debugger for Java/Kotlin

Ulyp is an instrumentation agent written specifically for this task. Recording all function calls along with return values and arguments is possible thanks to JVM bytecode instrumentation. This effectively eliminates the need of breakpoints in certain cases. It’s also feasible to record the execution flow in several apps at the same time via remote control. A developer is able to record and observe what happened in a distributed environment.

All data is dumped to the file a user specified via system properties. There are auxiliary threads which do the job of converting objects to binary format and writing to file. The resulting file can later be opened in UI app and entire flow can be analyzed.

Currently, Ulyp uses bytebuddy library which does an immense job of handling all the work of instrumentation and makes it extremely easy for all Java developers. The rest is relatively straightforward to implement. The ongoing blogposts will shed a light on how the tool is implemented. Right now, let’s move to action.

Case Study: Hibernate internals

Let’s start with on of the well known Java frameworks — Hibernate. We are going to use Spring to setup the demo and use Hiberante with H2 embedded data source. We will write very simple code snippet which takes a newly created entity and persists it to the database. We then observe the execution flow by recording it using Ulyp.

The demo is quite straightforward. Our entity is as follows:

@Entity
    public class Person {

        @Id
        @GeneratedValue
        private long id;
        @Basic
        private String firstName;
        @Basic
        private String lastName;
        @Basic
        private String phoneNumber;
        @Basic
        private int age;
        ...
    }

We also have a JPA repository to save entities.

    @Repository
    public interface PersonRepository extends JpaRepository<Person, Long> {

    }

There is also a service which is marked with transactional annotation, so that it opens a transaction whenever any of its’ public method is called.

@Service
@Transactional
public class PersonStoreService {

    @Autowired
    private PersonRepository repository;

    public void save(Person person) {
        repository.save(person);
    }

    public Person find(long id) {
        return repository.findOne(id);
    }
}

Now, we have main method which looks like this:

    public static void main(String[] args) {
        ApplicationContext context = new AnnotationConfigApplicationContext(Configuration.class);
        PersonStoreService store = context.getBean(PersonStoreService.class);

        Person person = new Person();
        person.setFirstName("John");
        person.setLastName("Doe");
        person.setAge(42);

        store.save(person);
        System.out.println("Stored: " + person);

        Person foundPerson = store.find(person.getId());
        System.out.println("Found: " + foundPerson);
    }

The whole code is available at the repo. After we execute the code, it will print the result:

Stored: org.example.hibernate.util.Person@52d14571
Found: org.example.hibernate.util.Person@75268ef2

We’d like to understand what exactly happened when we call the code. Let’s start using Ulyp. The only thing we need to do is to specify system properties, nothing else is changed.

-javaagent:/home/user/ulyp-agent-0.3.1-SNAPSHOT.jar
-Dulyp.file=/tmp/test-spring.dat
-Dulyp.methods=**.PersonStoreService.*
-Dulyp.record-constructors
-Dulyp.record-collections=JDK
-Dulyp.record-arrays

The first property tells the JVM that the agent should be used. The second property ulyp.file specifies file path where ulyp should store all recorded data. The next property tells Ulyp when it should start recording. In this case, whenever any method of class named PersonStoreService is called, ulyp will start recording all nested calls. ulyp.record-constructors tells to instrument and record constructors, and ulyp.record-collections=JDK allows to partially record collection values, but only for JDK standard library collections. The collections itself are not instrumented, i.e. Ulyp do not record calls like ArrayList.add, but can record some items from ArrayList if it is passed as an argument (or returned from) to some recorded method call.

After running the demo with properties set, we can upload the file to UI desktop app. The first thing we see is the list of recorded methods on the left.

Every entry in the list is a recorded method of some instance of PersonStoreService class. We can also see the duration of methods, as well as the number of recorded calls inside. There are 90,000 calls for just storing an entity with Spring, Hibernate and H2 inside. But keep in mind, there is a lot of bootrstrapping is done once the method is called for the first time. Next call would probably have less methods recorded. Duration is also quite high for storing just a single entity. There is an explanation to this — not only there was not enough time for JVM to warm up, but we also instrumented all third party classes, as well as recorded all method calls. There are benchmarks which measure the overhead of instrumenting and recording apps. The data shows that for a typical enterprise app, the overhead is around x3-x5 with proper warm up comparing to not using the agent at all.

Another thing you probably noticed, is that the name of the class is PersonStoreService$$EnhancerBySpringCGLIB$$fd7728fe rather that just PersonStoreService. That’s simply because the class is marked with @Transactional annotation. Spring will create a proxy for managing transactions, and then recording starts upon the proxy call.

Let’s dive deep into save method recorded calls. The recording data is presented in form of a tree with collapsible nodes. Every node is a recorded method call. Nodes are also marked with black pane which hints how many nested calls a node has comparing to the other nodes. The first thing we can see is that Spring proxy actually calls the instance of TransactionInterceptor:

If we dive deeper, we can see that our PersonStoreService is called after the transaction is started. Our transaction manager is an instance of JpaTransactionManager class. We can also see a call to TransactionInterceptor.commitTransactionAfterReturning where the opened transaction is supposedly commited.

The further exploration points where the instance of EntityManager is called:

At this point we see only simple class names (i.e. no package name), and it might be hard to tell which classes belong to Hibernate. That’s exactly why Ulyp can show full class names. Just select a node and hold the Shift button, and it you will see fully qualified names:

If we dive even deeper, we start seeing Hibernate SessionImpl in action. It calls JpaPersistEventListener.onPersist method:

The next method gets primary key value from the sequence for inserting the entuty into the table. First, JDBC statement is prepared. Then, the result set is obtained. Finally, we get primary key value (which is “1”) for storing our entity.

Here we start seeing JDBC layer, prepared statements to be exact. Those prepared statements are a part of H2 library:

Next, this newly obtained primary key is passed to JpaPersistEventListener. However, we do not see any inserts here! The only thing we see is attaching an entity to the instance of StatefulPersistenctConext. The actual inserting to the database will happen when Hibernate session is flushed later. Session flush may happen at either commit time, or when the entity table is queried inside the ongoing transaction.

In order to confirm this guess, we can check the recorded internals of commit method we saw earlier. Just dive into TransactionInterceptor.commitTransactionAfterReturning. After expanding some nodes, you can see the insert into the table with actual values:

Conclusion

This was the most simple demo for using Ulyp. Other cases include (but not limited to):

tracing distributed systems running in clouds
gathering gigs of data for later analysis
recording realtime apps where stopping a thread using a conventional debugger is not an option
finding inefficiencies in a gigantic frameworks

Ulyp doesn’t try to solve all the existing problems and it’s definitely not a silver bullet. The overhead of instrumenting could be quite high. You might now want to run it on production environment, but dev/test are usually ok. But if one can run their software app locally or on dev environment, it opens the opportunity to see things at completely different angle.

Ulyp is fully open-source and is available at https://github.com/0xaa4eb/ulyp

Part 1 has just covered a relatively basic case, Part2 will cover some more examples for Spring Boot. Future blog posts will cover more sophisticated use cases like recording several apps in a distributed system. Subscribe and stay tuned.