Showing posts with label Troubleshooting. Show all posts
Showing posts with label Troubleshooting. Show all posts

How to Improve Problem Solving Skills - A Developer's Guide


How to Improve Problem Solving Skills

How to Improve Problem Solving Skills

Jeffery Yuan

April 24, 2019

wait(0) - Timed_Waiting vs Waiting: Troubleshooting Practice


Tools - Troubleshooting Skills


Splunk

Search syntax
  • key=value AND OR NOT
  • | sort num(ip) desc, -str(url) | sort -value
  • | reverse
  • | top(or rare) limit=5 name
  • | head 5
  • | highlight fa, fb
  • | dedup fa
  • | stats count by method
  • | chart count by method url
  • | timechart span=15m count by url

earliest=“11/5/2017:20:00:00” latest=“11/12/2017:20:00:00”

Show only Certain Fields

| table field

(Not) contains a field

NOT fa=*

See all values in a field

| top a_number SourceName

Interesting Fields
  • Explore and know what values for a field
Events before or after X seconds
  • Show logs around current event
Visualizations Tab

Linux

crash or reboot?

ast -n2 -x shutdown reboot

  • If this reports a SYSTEM_SHUTDOWN followed by a SYSTEM_BOOT, all is well; however, if it reports 2 SYSTEM_BOOT lines in a row, then clearly the system did not shutdown gracefully

host $ip

Write Troubleshooting Friendly Program
  • Name your thread

How to Improve Problem Solving Skills



How to improve problem solving skills from Yun Yuan
Misc
How to test it (locally) and easily
How to verify whether it works easily
What's the short comings of your current approach?
Whether there is better approach?

How To Ask Questions The Smart Way

Problem Solving Practice - Redis cache.put Hangs


The Issue
After deployed the change: Multi Tiered Caching - Using in-process EhCache in front of Distributed Redis to test environment (with some other change and someone did some change in the server like restart), we found out that cache.put hangs when save data to redis.

Troubleshooting Process
First we tried to reproduce the issue in my local setup, it always works. But we can easily reproduce it in test environment.

This mde me think this maybe something related with the test environment.

Then I used kill -8 processId to generate several thread dumps when reproduce the issue in test machine. I found out some suspect:
"ajp-nio-8009-exec-10" #91 daemon prio=5 os_prio=0 tid=0x00007f49c400a800 nid=0x75db waiting on condition [0x00007f495333e000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at  RedisCache$RedisCachePutCallback(RedisCache$AbstractRedisCacheCallback).waitForLock(RedisConnection) line: 600
RedisCache$RedisCachePutCallback(RedisCache$AbstractRedisCacheCallback).doInRedis(RedisConnection) line: 564
at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:207)
at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:169)
at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:157)
at org.springframework.data.redis.cache.RedisCache.put(RedisCache.java:226)
at org.springframework.data.redis.cache.RedisCache.put(RedisCache.java:194)
at com.lifelong.example.MultiTieredCache.lambda$put$40(MultiTieredCache.java:130)
at com.lifelong.example.MultiTieredCache$$Lambda$18/1283186866.accept(Unknown Source)
at java.util.ArrayList.forEach(ArrayList.java:1249)
at com.lifelong.example.MultiTieredCache.put(MultiTieredCache.java:128)
at org.springframework.cache.interceptor.AbstractCacheInvoker.doPut(AbstractCacheInvoker.java:85)
at org.springframework.cache.interceptor.CacheAspectSupport$CachePutRequest.apply(CacheAspectSupport.java:784)
at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:417)
at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:327)
at org.springframework.cache.interceptor.CacheInterceptor.invoke(CacheInterceptor.java:61)

Check the code at RedisCache$AbstractRedisCacheCallback to understand how it works:
for operations like put/putIfAbsent/evict/clear, @cacheable with sync =true(RedisWriteThroughCallback), it check whether there is a key like cacheName~lock in redis, if exist, it will wait until it's gone.

This lock is created and deleted for @Cacheable with sync =true in RedisWriteThroughCallback which calls lock and unlock methods.

This made me check the settings in redis: after created the tunnel to redis, ran command: key cacheName~lock, I found out that it's indeed there.

Now everything make sense:
- we did set sync=true and run performance test, then restarted the server and removed it. The cacheName~lock was left there may be due to server restart. Due to the cacheName~lock, now all resid update api would not work.

After removed cacheName~lock in redis, everything works fine.

Take away
- When use some feature (@Cacheable(sync=true) in this case), know how it's implemented.

Troubleshooting - JsonMappingException: Already had POJO for id


The Problem
We have two entities with one-to-many relationships which references each other, but it failed with the exception:
com.fasterxml.jackson.databind.JsonMappingException: Already had POJO for id

The Fix
To easily troubleshoot the issue, I created a sample class like below:
@Data
@Accessors(chain = true)
@EqualsAndHashCode(of = {"employeeId"}, callSuper = false)
@JsonIdentityInfo(generator = ObjectIdGenerators.PropertyGenerator.class, property = "employeeId")
public static class Employee {
    private UUID employeeId;
    private String name;
    private Department department;
}
@Data
@Accessors(chain = true)
@EqualsAndHashCode(of = {"departmentId"}, callSuper = false)
@JsonIdentityInfo(generator = ObjectIdGenerators.PropertyGenerator.class, property = "departmentId")
@ToString(exclude = "employees")
private static class Department {
    private UUID departmentId;
    private String name;
    private Set<Employee> employees;

    public Set<Employee> getEmployees() {
        if (employees == null) {
            employees = new HashSet<>();
        }
        return employees;
    }
}


public static void main(String[] args) throws IOException {
    Employee e1 = new Employee().setEmployeeId(UUID.randomUUID()).setName("e1");
    Department d1 =
            new Department().setDepartmentId(UUID.randomUUID()).setName("oldD1").setEmployees(Sets.newHashSet(e1));
    e1.setDepartment(d1);
    ObjectMapper objectMapper = new ObjectMapper();

    String departmentStr = objectMapper.writeValueAsString(d1);
    objectMapper.writeValueAsString(e1);

    Department oldD1 = objectMapper.readValue(departmentStr, Department.class);

    Department newD1 = new Department().setDepartmentId(d1.getDepartmentId()).setName("newD1");
    newD1.getEmployees().addAll(oldD1.getEmployees());
    // without the following statements: it will throw
    // com.fasterxml.jackson.databind.JsonMappingException: Already had POJO for id
    // for (Employee e : oldD1.getEmployees()) {
    // e.setDepartment(newD1);
    // }

    departmentStr = objectMapper.writeValueAsString(newD1);
    System.out.println("new department: " + departmentStr);
    // now read it back will throw sonMappingException: Already had POJO for id
    Department newNewD1 = objectMapper.readValue(departmentStr, Department.class);
    System.out.println("---" + newNewD1);
}
This reproduces the issue, and from the output:
new department: {"departmentId":"e3e0e676-0c52-493d-8f49-bedde05cbb11","name":"newD1","employees":[{"employeeId":"6b7bbbec-8be6-4423-a4ef-af7924df177b","name":"e1","department":{"departmentId":"e3e0e676-0c52-493d-8f49-bedde05cbb11","name":"oldD1","employees":["6b7bbbec-8be6-4423-a4ef-af7924df177b"]}}]}
I found that after I changed the department to newD1, the employee still refers to old department object with department name: oldD1.

This leads to my fix like below: after I made change to the department object, make sure the employees refers to the new department object.

// without the following statements: it will throw
// com.fasterxml.jackson.databind.JsonMappingException: Already had POJO for id
for (Employee e : oldD1.getEmployees()) {
  e.setDepartment(newD1);
}

Miscs
We need exclude employees from Department's toString: @ToString(exclude = "employees")
- Otherwise it would throw java.lang.StackOverflowError
Likewise, we need exclude employees from @EqualsAndHashCode.

Iterator vs Iterable - Don't use Iterator as cache value


The Problem
Can you figure it out what's the issue in the following code?
@Cacheable(key = "#appName", sync = true)
public Iterator<Message> findActiveMessages(final String appName) {}

Iterator vs Iterable
In most case we can use either Iterable or Iterator, but there is one key difference: 
- if we need traverse and get the value multiple times, then we can't use Iterator.

As once you loop all the data in the iterator, the iterator points to the last position +1 and is not usable anymore. Now if we can iterator.haneNext(), it would be false; if we try to loop it again, we will get empty data.

Unless you define it as ListIterator and manually move back one by one till reach the beginning, which is inefficient and we don't usually code that way.

Takeaway
Don't use Iterator when need traverse multiple times
Don't use Iterator as cache value
Don't store Iterator in collection.

Troubleshooting Practices


Troubleshooting is important and inevitable for engineers when we try to figure out why the code doesn't work; it also improves our problem solving skills: what steps to take to quickly find the root cause.

This articles is to reflect the process that I took to find the root cause.

Can't deploy Spring-boot application to tomcat
- SpringBootServletInitializer.configure is not called at all

During dev, the team is running spring-boot application as java application. But later when we deploy to the cloud, we need run it as web application. The developer tried it but doesn't work.

We found out it's because the dev specifies 2.5 in web.xml unintentionally and Spring-boot requires Servlet 3.0 by default.
http://docs.spring.io/spring-boot/docs/current/reference/html/howto-traditional-deployment.html

jackson-module-scala: NoSuchMethodError due to intellij
Recently when I ran tests in intellij, it throws the following exception:
java.lang.NoSuchMethodError: scala.util.matching.Regex.unapplySeq(Ljava/lang/CharSequence;)Lscala/Option;
at com.fasterxml.jackson.module.scala.JacksonModule$.version$lzycompute(JacksonModule.scala:30)
at com.fasterxml.jackson.module.scala.JacksonModule$.version(JacksonModule.scala:26)
at com.fasterxml.jackson.module.scala.JacksonModule$class.version(JacksonModule.scala:49)
at com.fasterxml.jackson.module.scala.DefaultScalaModule.version(DefaultScalaModule.scala:19)
at com.fasterxml.jackson.databind.ObjectMapper.registerModule(ObjectMapper.java:701)

Seems it's caused by jackson-module-scala, but I use mvn dependency:tree and dependency:copy-dependencies to check all thing looks good: we use scala-2.11 and jackson-module-scala_2.11. Also if I ran the test in command line, it works.

This made me think maybe this is because of intellij. 
I added a breakpoint and run: scala.util.Properties.versionString in debug mode, it's 2.10.6. This is strange. Then I check external libraries in intellij, there are indeed multiple scala-library versions: 2.10.6 and 2.11.8.

In our current projects, we don't use scala-library-2.10.6 anywhere. Maybe previously we use scala 2.10.6, later we upgraded to 2.11. But intellij still keeps reference to old scala in external libraries.
- no effects when reimport all maven projects

The workaround is to delete .idea/libraries internals and restart IntelliJ and reimport projects.

ClassNotFoundException: StandardSessionIdGenerator because we overwrite tomcat.version
- Asked by team mate to help solve this issue
Usually this is because of version conflict. We use spring-boot 1.5, but the tomcat-embed-core is 7.0.65. This looks suspicious. Then I checked the pom.xml. This makes me check how spring-boot specifies its version. search tomcat-embed-core in https://github.com/spring-projects, found 
spring-boot-starters/spring-boot-starter-tomcat/pom.xml and spring-boot-dependencies/pom.xml:
<tomcat.version>8.5.6</tomcat.version>

But we also defined same property: tomcat.version to 7.0.50 in project's pom.xml for some tomcat dependencies we used. This overwrites spring-boot property. So now spring-boot use tomcat-embed-core 7.0.65 which doesn't have StandardSessionIdGenerator class.

The fix is to change our own property to xx. tomcat.version and also bumped its version to same as spring-boot.
- spring-boot should add prefix such as spring.boot to these properties.

Find code by running sample code and debugging it
Build Web Service APIs to Update Solr's Managed Resources (stop words, synonyms)
I need figure out how to get address of one of live solr nodes by using CloudSolrClient.  I know solrJ uses apache http client to send requests, somewhere it needs get addresses of solr nodes, so I write some sample code which sends invalid request, solrJ will throw exception, then I check the stack trace form the log and find out the code that I need at org.apache.solr.client.solrj.impl.CloudSolrClient.sendRequest(SolrRequest, String).

Troubleshooting Spring Security Multiple JSESSIONID Cookie Issue


The problem
There is one weird issue in our application that sometimes after login, it redirects to index.html but it failed to load.

The problem only happens occasionally.

Troubleshooting Process
Use chrome devtool to check requests in network panel, some protected api works fine, but some fails and sends redirect to login page due to 302 Found. 
-- This is weird. Usually it should fail/succeed for all. This leads me to check the difference between succeeded and failed requests.

Then I check the cookie settings in chrome://settings/cookies
I saw there are 2 JSESSIONID, one in path /, one in path /v1/data

Reproduce the issue
Next I tried to find a way to reliably and conveniently reproduce the issue, then found out that:
The problem happens if I first visits apis like v1/data/products. No problem if I first visits /login or /index.html.

Then I check more detail at the request and response in network panel.
Found that when first access v1/data/products, the response is 302, and redirect to login page, the cookie is:
Set-Cookie:JSESSIONID=8C70B083FB7FEAD57F6B6ADF9817E48C; Path=http://localhost/myapp_jbuild_number/; Secure; HttpOnly

Spring created one session for this anonymous user so later it can redirect to original page after login. The session 8C70B083FB7FEAD57F6B6ADF9817E48C is anonymous user.

After login, for api that succeeded, such as v1/xxx, it uses right JSESSIONID.

But for apis failed like v1/data/xx, there are 2 JSESSIONID, in the request headers.
Cookie:JSESSIONID=8C70B083FB7FEAD57F6B6ADF9817E48C; JSESSIONID=1BE7FFCA12C3882AE6F651DBA3759964

As the anonymous user session 8C70B083FB7FEAD57F6B6ADF9817E48C is for path v1/data
the logined user session 1BE7FFCA12C3882AE6F651DBA3759964 is for /, so the server uses the anonymous user session 8C70B083FB7FEAD57F6B6ADF9817E48C.

This is why the request to v1/data/xx failes and returns 302 and redirect to login page.

2016-10-13 00:09:56:0934 INFO  2268116 [ajp-nio-8009-exec-2] Spring Security Debugger    -
New HTTP session created: 8C70B083FB7FEAD57F6B6ADF9817E48C
Request received for GET '/v1/data/xxxx':
cookie: JSESSIONID=8C70B083FB7FEAD57F6B6ADF9817E48C; JSESSIONID=1BE7FFCA12C3882AE6F651DBA3759964;
2016-10-13 00:10:10:0330 DEBUG 2281512 [ajp-nio-8009-exec-4] o.s.s.w.a.AnonymousAuthenticationFilter    - Populated SecurityContextHolder with anonymous token: 'org.springframework.security.authentication.AnonymousAuthenticationToken@6faa6108: Principal: anonymousUser; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@ffff10d0: RemoteIpAddress: 173.230.196.25; SessionId: 8C70B083FB7FEAD57F6B6ADF9817E48C; Granted Authorities: ROLE_ANONYMOUS'

But Why created one cookie JSESSIONID at path v1/data?
At first, I thought it's because of spring.
But after several hours, I check the request and response again, and wonder why the path is like: Path=http://localhost/myapp_jbuild_number/

This leads me to check apache httpd configuration, and found out the root cause:
ProxyPassReverseCookiePath / http://localhost/myapp-version_jbuild_number/

This is not right and cause wrong path in response header: Set-Cookie: Path=http://localhost/myapp_jbuild_number/

After removed it, it works.
the path in response header is Set-Cookie: ... Path=/;

Misc: WebSecurityConfigurerAdapter
To enable the DebugFilter in spring security, configure WebSecurity in WebSecurityConfigurerAdapter subclass. It will log information (such as session creation) to help the user understand how requests are being handled by Spring Security - But never do this in production.
public void configure(WebSecurity web) throws Exception {
    web.debug(true);
}


ProxyPassReverseCookiePath internal-path public-path
- Rewrite the path string in Set-Cookie headers. If the beginning of the cookie path matches internal-path, the cookie path will be replaced with public-path.

Happy Troubleshooting.

InitializationError When Use Spring Test + JUnit


The Problem
When we tried to use Spring Unit Testing framework with JUnit in our project, the simple test failed with error: "initializationError[Runner: JUnit 4]"

I imported the SpringJUnitIntro project to eclipse, it works.
But if I copied all classes to our project, it failed with initializationError. So this should be our project configuration issue.

Google Search, didn't find any thing quite useful.

Then I ran the test in debug mode, it stopped at 
Thread [main] (Class load: SpringJUnit4ClassRunner)
owns: Object  (id=24)
Class.getDeclaredConstructors0(boolean) line: not available [native method]
Class.privateGetDeclaredConstructors(boolean) line: 2671
Class.getConstructor0(Class[], int) line: 3075
Class.getConstructor(Class...) line: 1825
AnnotatedBuilder.buildRunner(Class, Class) line: 29
AnnotatedBuilder.runnerForClass(Class) line: 21
AnnotatedBuilder(RunnerBuilder).safeRunnerForClass(Class) line: 59 //\\
AllDefaultPossibilitiesBuilder.runnerForClass(Class) line: 26
AllDefaultPossibilitiesBuilder(RunnerBuilder).safeRunnerForClass(Class) line: 59
ClassRequest.getRunner() line: 26
FilterRequest.getRunner() line: 31
JUnit4TestLoader.createFilteredTest(Class, String, String[]) line: 77
JUnit4TestLoader.createTest(Class, String, String[], RemoteTestRunner) line: 68
JUnit4TestLoader.loadTests(Class[], String, String[], RemoteTestRunner) line: 43
RemoteTestRunner.runTests(String[], String, TestExecution) line: 444
RemoteTestRunner.runTests(TestExecution) line: 678
RemoteTestRunner.run() line: 382
RemoteTestRunner.main(String[]) line: 192

Then I use F7 to step return, an AnnotatedBuilder(RunnerBuilder).safeRunnerForClass(Class) line: 61, I found the root cause of the issue.

The Throwable e is java.lang.ExceptionInInitializerError,  run "e.printStackTrace();" in Eclipse Display view, then I found the root cause of the issue:
java.lang.ExceptionInInitializerError
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
  ...
Caused by: java.lang.IllegalStateException: SpringJUnit4ClassRunner requires JUnit 4.12 or higher.
at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.(SpringJUnit4ClassRunner.java:102)
... 18 more

org.springframework.test.context.junit4.SpringJUnit4ClassRunner:

static {
  if (!ClassUtils.isPresent("org.junit.internal.Throwables", SpringJUnit4ClassRunner.class.getClassLoader())) {
    throw new IllegalStateException("SpringJUnit4ClassRunner requires JUnit 4.12 or higher.");
  }

  withRulesMethod = ReflectionUtils.findMethod(SpringJUnit4ClassRunner.class, "withRules",
      FrameworkMethod.class, Object.class, Statement.class);
  if (withRulesMethod == null) {
    throw new IllegalStateException("SpringJUnit4ClassRunner requires JUnit 4.12 or higher.");
  }
  ReflectionUtils.makeAccessible(withRulesMethod);
}

At org.junit.internal.runners.ErrorReportingRunner.describeCause(Throwable), the inner exception is lost

  private Description describeCause(Throwable child) {
      return Description.createTestDescription(fTestClass,
              "initializationError");
  }
After upgrade JUnit from 4.11 to 4.12, everything works fine.

Lesson Learned
Try run in debug mode
Use latest version of a library
Version conflict is a common issue in Java.
-- Use different versions of same library
-- Use lower version than supported: 
-- Check least version of X supported
Spring test framework requires JUnit 4.12 or higher. 
-- Check what version of X the library support
-- Check project readme
Example: spark-csv is for sprak 1.x, has been inlined in Apache Spark 2.x
-- Check project dependcy file: pom.xml, build.sbt, build.gradle etc
Example: spark-solr still uses spark 1.5 and use solr 6.x.

Skills for developers:
What's more important is how to debug and find the root cause.

How to Troubleshoot and Debug - Programmer Skills


Related: How to Solve Problems
Troubleshooting is fun
We can learn something new, avoid making same mistake in future.
it brings us accomplishment and satisfaction.

How to Troubleshoot and Debug

Check and save current state(logging)
We may not recreate the problem easily, so analyze the problem and save logging first.

Understand the problem first
-- Especially when trouble shoot problem for others(rookie).
First take some time to understand the symptom, what the symptom means, whether it's really a problem
Don't just make some change blindly without understanding the symptom
Check error code, understand how the user is writing the code

Understand the environment first
-- Especially asked to help trouble shoot in other's project which you are not familiar at all
-- Don't blindly think others made some simple/stupid mistake, or same mistake you made before
  -- You din't find some configuration file - it may be because you find it in wrong folder
-- Know how to quickly search/debug in linux
-- Most time, the problem/root cause is simple, or just need some configuration change or there is no problem at all

List/think about what may be the root cause
- trouble shooting problem is thinking what may go wrong
- how it's likely caused by this?
- how easily we can verify it?

- if not likely and not easily to verify it, try/list other possible root cause/approaches first

Read/Check the Log
Change the logging level to know more abut the internal
For example, if we are using spring security library: then change level of org.springframework.security to debug in dev environment.

Check/Use IDE
- The IDE can help to detect problems.
- Eclipse' problems view may tell problems that cause project not build, or mistake in configuration files such as web.xml.

Reproduce the problem (faster)
Try to reproduce the problem locally in our own setup
-- It's much easier to trouble shooting in our local setup, we can do all tricks add breakpoint, change variable value, force return, drop frames to rerun etc.
-- Sometimes the problem is related with data, it only happens with the data in x line with its data. We can change local setup to point to remote data (via creating tunnel etc). - This is much easier to remote debug code in remote server.

Simplify the suspect code
Create simple test cases to reproduce it

If possible, debug and test locally
For example, we can change local setup to use data in remote setup(test or sometimes production lines).

Remote debug if can't debug locally 
- but last resort, slow and sometimes impossible

Use condition breakpoint to change behavior dynamically
Use display view/force return to change behavior
Force the execution of suspect path
-- throw exception, change value etc

Source code is always the ultimate truth
- Don't assume or think ..., check the code to verify it.
- Always find the related code and understand it
  - how it works, how it gets called, how to configure it
  - You can't troubleshoot without know understanding the code first
- We can find examples/working code
- We can understand how/why the code works by running and debug the code

Check the code and log together

Change the Code to Help Debug
-- Add logging


Construct and test hypotheses

- First verify the most-likely, easy-to-verify ones


Google Search using the error message with library, class and method name
Search source code in Github/Eclipse
Search log: use linux command:(f|e)grep

Compare the difference between the code and the failed code
-- Compare different version in git(hub).
-- Search company's code base and find similar code
-- Others may already fixed same problems

If still gets stuck:
Take time to learn the framework/feature etc
Sleep on it, try to solve it later.

Scripting
Write test code using scripting or other languages

Ask in StackOverflow, product's forum
Read the Doc/JavaDoc

Solve problems quickly but find root cause slowly
- Solve problems quickly so others can move on
- But take time to find root cause or reflect if it matters

Collaboration
Ask questions
-- When help solve problems for others or debug other's code.
Get more information as much as possible - when help others
Provide more information when ask help

When work on urgent issues with others
-- Collaborate with others timely
-- Let others know what you are testing, what's your progress, so there is no overlap.

Reflection: Lesson Learned
How we find the root cause, why it takes so long

What we learned
What's the root cause

Why we made the mistake

How we can prevent this happens again

Share the knowledge in the team

Java Lambda-Enabled Concurrency - Variables may be Changed Unexpectedly


In my last post, I explained that Don't Use Mutable Variables in Java Lambda Concurrency, but sometimes, variables may be changed unexpectedly.

The Problem
When optimize performance of function that exports solr data as csv, I add the logger.debug statements, then find out the test throws ConcurrentModificationException:
Caused by: java.util.ConcurrentModificationException: null
at java.util.LinkedHashMap$LinkedHashIterator.nextNode(LinkedHashMap.java:711) ~[na:1.8.0_40]
at java.util.LinkedHashMap$LinkedEntryIterator.next(LinkedHashMap.java:744) ~[na:1.8.0_40]
at java.util.LinkedHashMap$LinkedEntryIterator.next(LinkedHashMap.java:742) ~[na:1.8.0_40]
at org.apache.solr.common.params.ModifiableSolrParams.toString(ModifiableSolrParams.java:201) ~[solr-solrj-5.2.1.jar:5.2.1
at java.text.MessageFormat.subformat(MessageFormat.java:1280) ~[na:1.8.0_40]
at java.text.MessageFormat.format(MessageFormat.java:865) ~[na:1.8.0_40]
at java.text.Format.format(Format.java:157) ~[na:1.8.0_40]
at java.text.MessageFormat.format(MessageFormat.java:841) ~[na:1.8.0_40]
at AbstractSolrRepository.findAllAsyncImpl(AbstractSolrRepository.java:236)

The code looks like below:
@Nonnull private List<Future<List<T>>> findAllAsync(final SolrParams originalParams, final int readSize,
        final long totalCount) {
    final ModifiableSolrParams query = new ModifiableSolrParams(originalParams);
    query.set(CommonParams.ROWS, readSize);
    final List<Future<List<T>>> futures = new ArrayList<>();
    int start = 0;
    while (start < totalCount) {
        final ModifiableSolrParams solrParams = new ModifiableSolrParams(query);
        solrParams.set(CommonParams.START, start);
        final Stopwatch stopWatch = Stopwatch.createStarted();

        futures.add(executor.submit(() -> querySolr(solrParams)));
        if (logger.isDebugEnabled()) {
            logger.debug(MessageFormat.format("executor.submit took {0}, params: {1}",
                    stopWatch.elapsed(TimeUnit.MILLISECONDS), solrParams));
        }
        start += readSize;
    }
    return futures;
}
-- the code is much simplified later. Check final code here.
We submit the query task into thread pool, and want to log how long the submit takes - when all threads in the thread pool are busy, and its queue is full, the submit will block. I want to figure out whether it happens, whether I need change the thread pool settings.
-- Check AsyncConfigurer configuration code here.

It feels strange, so I decide to figure out why.

The Root Cause
ModifiableSolrParams uses LinkedHashMap to store data, its toString loops the LinkedHashMap. 
From the exception, it means that the ModifiableSolrParams is changed during the for-loop in toString() method.

So I check what changed in ModifiableSolrParams, find out solrClient.query adds _stateVer_=cobradb.survey_response:2903.

Then I go to solr github repos and search _stateVer_, and find CloudSolrClient and public static final String STATE_VERSION = "_stateVer_";.

Then I add a break point to places where STATE_VERSION is used and find the following code:
org.apache.solr.client.solrj.impl.CloudSolrClient.requestWithRetryOnStaleState(SolrRequest, int, String)
    if (request.getParams() instanceof ModifiableSolrParams) {
      ModifiableSolrParams params = (ModifiableSolrParams) request.getParams();
      if (stateVerParam != null) {
        params.set(STATE_VERSION, stateVerParam);
      } else {
        params.remove(STATE_VERSION);
      }
    }

The ConcurrentModificationException will happen when the code above and the for-loop in ModifiableSolrParams.toString runs at same time.

Search - Fix same problem
Next I search logger.*query and logger.*param to check whether we made same mistake.

Solr - Tips and Tricks


Admin UI
http://127.0.0.1:8983/solr/#/~cloud?view=tree
bin/solr help
bin/solr status
bin/solr healthcheck
bin/solr stop -all
(bin/solr start -cloud -s example/cloud/node1/solr -p 8983 -h 127.0.0.1)  && (bin/solr start -cloud -s example/cloud/node2/solr -p 7574 -z 127.0.0.1:9983 -h 127.0.0.1) && (bin/solr start -cloud -s example/cloud/node3/solr -p 6463 -z 127.0.0.1:9983 -h 127.0.0.1)

Delete docs:
change *;* to your query
update?commit=true&stream.body=<delete><query>*:*</query></delete>

https://wiki.apache.org/solr/SearchHandler
Use invariants to lock options and overwrite values client passes.
Use appends to append options, use defaults to provide default options.

Request Paramters
distrib=false - only query current core

debugQuery
debug=query/results/timing

explainOther
debug=results&explainOther=id:MA*

Range Query inclusive: [a to b]
exclusive: {a to b} - it's not ().
mixed: [a to b} {a to b]

Negative Query
Query empty fields: -field:*
field is empty or is abc: (*:* OR -field:*) OR field:abc
(*:* -id:1) OR id:1 - return all docs
http://stackoverflow.com/questions/634765/using-or-and-not-in-solr-query
-foo is transformed by solr into (*:* -foo)
The big caveat is that Solr only checks to see if the top level query is a pure negative query!

Solr zkcli
zkcli.sh -zkhost zooServer:port  -cmd putfile /configs/solrconfig.xml solrconfig.xml
zkcli.sh -zkhost zooServer:port  -cmd get /configs/schema.xml

To get solrcloud nodes info(such as ip address)
java -classpath "*" org.apache.solr.cloud.ZkCLI -zkhost myzkhost -cmd get /clusterstate.json | grep base_url
zkcli.sh -zkhost myzkhost:port -cmd get /clusterstate.json

Rest API
solr/collection/config
solr/collection/config/requestHandler
solr/collection/schema
solr/collection/schema/version
solr/admin/collections?action=RELOAD&name=$NAME

SolrJ Field Annotation
Map Dynamic fields to fields
@Field("supplier_*")
Map> supplier;

@Field("sup_simple_*")
Map supplier_simple;

@Field("allsupplier_*")
private String[] allSuppliers;

@Field(child = true)
Child[] child;

Staring Solr
-m 2g: Start Solr with the defined value as the min (-Xms) and max (-Xmx) heap size for the JVM.

bin/solr stop -all

(bin/solr start -cloud -s example/cloud/node1/solr -p 8983 -h 127.0.0.1 -m 2g)  && (bin/solr start -cloud -s example/cloud/node2/solr -p 7574 -z 127.0.0.1:9983 -h 127.0.0.1 -m 2g) && (bin/solr start -cloud -s example/cloud/node3/solr -p 6463 -z 127.0.0.1:9983 -h 127.0.0.1 -m 2g)
-- Use -h 127.0.0.1 so solr can continue to work even ip changed.

Extending Solr
Implement the SolrCoreAware interface in custom RequestHandler to get SolrCore in inform method.

Customize and extend DocumentObjectBinder

Get solr static fields
SolrServer solrCore = new HttpSolrServer("http://{host:port}/solr/core-name");
SolrQuery query = new SolrQuery();

query.setRequestHandler("/schema/fields");
// query.add(CommonParams.QT, "/schema/fields");
QueryResponse response = solrClient.query(query);
NamedList responseHeader = response.getResponseHeader();
ArrayList fields = (ArrayList) response.getResponse().get("fields");
for (SimpleOrderedMap field : fields) {
    Object fieldName = field.get("name");

}

Solr Internals
replicationFactor

The Solr replicationFactor has nothing to do with quorum. Solr uses Zookeeper's Quorum sensing to insure that all Solr nodes have a consistent picture of the cluster.

openSearcher and hardCommit
- Soft commit always opens new searcher.
- openSearcher only makes sense for hardcommit

Use config api to change solr settings dynamically

Use JSON API, but be aware SolrJ may not work with JSON API in some cases.

Solr Facet APIs
http://yonik.com/json-facet-api/
http://yonik.com/solr-facet-functions/

Don't forget facet.mincount=1

update.distrib
=toLeader when one replica sends this doc to it's leader=
=fromLeader when the doc's leader sends it to its followers

Solr Nested Objects
Define _root_ field

Use [child] - ChildDocTransformerFactory to return child documents

admin collection apis
/admin/collections?action=CLUSTERSTATUS

curl http://localhost:8983/solr/mycollection/update -X POST -H 'Content-Type: application/json' --data-binary @atomic.json

Zookeeper
Clean ZK data - link
run java -cp zookeeper-3.4.6.jar:conf org.apache.zookeeper.server.PurgeTxnLog  ../zoo_data/ ../zoo_data/ -n 3

Access solr cloud via ssh tunnel
Create a tunnel to zookeeper and solr nodes
- But when solrJ queries zookeeper, it still returns the external solr nodes that we can't access directly
Add a conditional breakpoint at CloudSolrClient.sendRequest(SolrRequest, String)
- before  LBHttpSolrClient.Req req = new LBHttpSolrClient.Req(request, theUrlList);
theUrlList.clear();
theUrlList.add("http://localhost:18983/solr/searchItems/");
theUrlList.add("http://localhost:28983/solr/searchItems/");

return false;

Solr suggester
It supports filter on multiple fields. Just copy these fields to the contextFilterFeild.

Troubleshooting
400 Unknown Version - when run curl solr
- Maybe u need encode query parameters

Debug Solr Query
http://splainer.io/

APIs
http://localhost:8983/solr/admin/collections
?action=LIST&wt=json

solr/admin/collections?action=OVERSEERSTATUS
overseer_queue_size
overseer_work_queue_size

admin/mbeans?key=fieldCache&stats=true

Coding
Watches are one time triggers

SolrJ
*SolrClient
request(SolrRequest)
.getZkStateReader()

GenericSolrRequest 
solrClient.request(new GenericSolrRequest(SolrRequest.METHOD.GET, "/admin/mbeans", params))
(NamedList<Object>) nl.findRecursive("solr-mbeans", "CACHE", "fieldCache", "stats");</Object>

Use Zookeeper client
./zkCli.sh -server localhost:9983
ls(delete) path
create path data // data can be ''
get path
stat /overseer/collection-queue-work
get /overseer/collection-queue-work/qn-0001379031
Create chroot path
create /the-chroot-path []

Building Troubleshooting Friendly Application - Using Feature Toggle


In last post, I talked about how to change log level and add diagnosis information per request at runtime. It helps us to debug and trouble shooting problems in production environment.

But at that time, we use X-DEBUG-KEY header,  check whether it matches the key at server side, if so enable this feature. 

This is unsafe(as we may return internal implementation information to client). - even we encrypt the X-DEBUG-KEY in the source code and change it before push to production.

Recently, we developed a common feature toggle service. So now we can use the feature toggle service to control who can use the debug request feature and turn it on/off dynamically at server side.
FeatureService
Admin can create/update/delete feature. The feature can be stored in database(sql or nosql).
Client will call isFeatureOn with feature name and a map. isFeatureOn will get the feature from db and check whether it's on. It will return Decision.NEUTRAL if not exist.
public interface FeatureService {
    Decision isFeatureOn(String name, Map<String, Object> variables);
    public Optional<Feature> getFeature(final String name);
    public void addFeature(Feature feature);
    public void updateFeature(Feature feature);
    void deleteFeature(Iterator<String> iterator);
    Collection<Feature> getAllFeatures();
}
Feature and Expression
Feature contains a list of expression, and will call the expression's apply method to check whether the feature should be on or off. 


Currently we only support AnyMatchExpression, PercentageExpression and ScriptExpression, but it can be easily extended.

Notice we can use the optional ttlSeconds to control how long the feature will be on, after that it will be expired. This adds another safety layer to the feature toggle service.

-- We annotate updateTime with View.Viewable.class, so outside API can only view it but can't update it: check Using Jackson JSON View to Protect Mass Assignment Vulnerabilities

public class Feature {
    private String name;
    private String appId;
    /**
     * This is used as extension, in case later we support rejectFirst.
     */
    private boolean acceptFirst = true;
    public Feature() {}
    @JsonView(View.Editable.class)
    private List<Expression> expressionList = new ArrayList<>();
    @JsonView(View.Editable.class)
    protected int ttlSeconds = -1;

    @JsonView(View.Viewable.class) // all other properties are marked as Editable, except updateTime
    private Date updateTime;

    @JsonIgnore
    public boolean isEffective() {
        if (ttlSeconds != -1) {
            if (updateTime == null) {
                logger.error("Invalid feature {}, updateTime is null while timeToLive is {}", name, ttlSeconds);
                throw new XXException(ErrorCode.INTERNAL_ERROR,
                        String.format("Invalid feature %s: ", getName()));
            }
            final MutableDateTime expiredTime = new MutableDateTime(updateTime);
            expiredTime.addSeconds(ttlSeconds);

            return expiredTime.isAfterNow();
        }
        return true;
    }
    public Decision isFeatureOn(final Map<String, String> variables) {
        if (hasExpired()) {
            return Decision.NEUTRAL;
        }
        final List<Expression> expressionList = getExpressionList();
        for (final Expression expression : expressionList) {
            if (expression.apply(variables).equals(Decision.ACCEPT)) {
                return Decision.ACCEPT;
            }
        }
        return Decision.NEUTRAL;
    }
    // ignore equals, hashcode, toString, getter, setter..    
}    

@JsonIgnoreProperties(ignoreUnknown = true)
@org.codehaus.jackson.annotate.JsonIgnoreProperties(ignoreUnknown = true)
@JsonTypeInfo(use = JsonTypeInfo.Id.NAME, include = JsonTypeInfo.As.PROPERTY, property = AbstractExpression.FIELD_TYPE,
        visible = false)
@JsonSubTypes({@Type(value = PercentageExpression.class, name = PercentageExpression.TYPE),
        @Type(value = AnyMatchExpression.class, name = AnyMatchExpression.TYPE),
        @Type(value = ScriptExpression.class, name = ScriptExpression.TYPE)})
public interface Expression {
    public Decision apply(Map<String, Object> variables);
}

public class AnyMatchExpression extends AbstractExpression {
    public static final String TYPE = "anyMatch";
    /**
     * which variable name to look up
     */
    private String variableName;

    private boolean caseInsensitive;
    @JsonProperty("set")
    private Set<String> set = new HashSet<>();

    public AnyMatchExpression() {
        type = TYPE;
    }
    @Override
    public Decision apply(final Map<String, Object> variables) {
        final Object object = variables.get(variableName);
        if (object != null) {
            final Iterable<String> idIt = SomeUtil.COMMA_SPLITTER.split(object.toString());
            for (String id : idIt) {
                if (caseInsensitive) {
                    id = id.toLowerCase();
                }
                if (set.contains(id)) {
                    return Decision.ACCEPT;
                }
            }
        }
        return Decision.NEUTRAL;
    }
    /**
     * Precondition: There is no null value in the set. Otherwise it will throw NPE.
     */
    public void setSet(final HashSet<String> set) {
        if (caseInsensitive) {
            final HashSet<String> lowercaseSet = new HashSet<>();
            for (final String word : set) {
                lowercaseSet.add(word.toLowerCase());
            }

            this.set = lowercaseSet;
        } else {
            this.set = set;
        }
    }
    // ignore toString, getter, setter..
}
public class PercentageExpression extends AbstractExpression {
    public static final String TYPE = "percentage";
    /**
     * a value between 0 and 100
     */
    private int percentage;
    public PercentageExpression() {
        type = TYPE;
    }
    @Override
    public Decision apply(final Map<String, Object> variables) {
        if (percentage == 100) {
            return Decision.ACCEPT;
        }
        final Random random = new Random();
        final int rValue = random.nextInt(100);
        if (rValue < percentage) {
            return Decision.ACCEPT;
        }
        return Decision.REJECT;
    }
}
Check Whether Debug Request Feature is On
Now we can check whether the debug request feature is turned on for this user. - we only do this when X_DEBUG_REQUEST header exists. - Of course we cache the Feature object, so we don't do db call every time.
protected void checkDebugRequestFeature(final ContainerRequest request) {
    if (debugRequestEnabled) {
        final String debugRequest = request.getHeaderValue(X_DEBUG_REQUEST);
        if (StringUtils.isNotBlank(debugRequest)) {
            final User user = getUserObjectHere();

            if (SomeUtil.isFeatureOn(SomeUtil.FEATURE_DEBUG_REQUEST, user, featureService)) {
                MDC.put(X_DEBUG_REQUEST, debugRequest);
                RequestContextUtil.getRequestContext().setEnableDebug(Boolean.valueOf(debugRequest));
            } else {
                RequestContextUtil.getRequestContext().setEnableDebug(false);
            }
        }
    }
}
Other User Cases Using Feature Toggle
Feature Toggle is a quite simple but powerful service. With it, we can do A/B testing, we can test and trouble shooting on productions: such as we can allow some specific users to debug request, to mock user etc.

Building Application to Be Troubleshooting Friendly


The Problem
There is always bug in code that will be found later in production, and in some cases we can't easily reproduce it in test environment.

Ideally we want to rerun the request, check the log in server or maybe change the log level to info or debug.

But usually we can't or at least not that easy: to check the realtime log in production machine or login to it, we have to talk with operation team or open ticket and get it approved; let alone restart the machine to change log level.

Solution
  • Change log level per request.
  • Return diagnosis information in API response.
Implementation
When client sends request with headers: X-Debug-Request=true, and X-DEBUG-KEY equals the encrypted debug.key defined in properties file, the application will change some loggers to debug level(so it will print more logging to help us trouble shooting the problem) and add diagnosis info in response. 

We can put the diagnosis info in header or request body. In this example, we choose to put it in request body.

-- We use debug.key to protect this feature and change it frequently (in each deployment).

The response would be like:
-- We wrap the real response in data tag, so we can easily extend it to add other related data later. 
{
 "data": { // here it can be an object(for getById) or an array(for query)
 }
 "diagnosis": [] // list of string that may help diagnose the problem
 // here can be some pagination meta data 
}

Code
The following code uses Logback and Jersey 1.

PerRequestTurboFilter
public class PerRequestTurboFilter extends DynamicThresholdFilter {
    @Override
    public FilterReply decide(final Marker marker, final Logger logger, final Level level, final String s,
            final Object[] objects, final Throwable throwable) {

        final String loggerName = logger.getName();

        if (loggerName.startsWith("com.myapp") || loggerName.startsWith("org.apache.http")
                || loggerName.startsWith("httpclient.wire")) {
            return super.decide(marker, logger, level, s, objects, throwable);
        }
        addMesToRequestConext(reply, loggerName, msg);
        return FilterReply.NEUTRAL;
    }
    protected void addMesToRequestConext(final FilterReply reply, final String loggerName, final String msg,) {
        final String mdcValue = MDC.get(getKey());
        if (mdcValue != null && reply.equals(FilterReply.ACCEPT) && StringUtils.isNotBlank(msg)
                && loggerName.startsWith("com.myapp")) {
            RequestContextUtil.getRequestContext().addDiagnosis(msg);
        }
    }
} 
PerRequestTurboFilter extends Logback DynamicThresholdFilter, it will only change logger level for com.app and apache http and httpclient. If MDC contains X-Debug-Request, and its value is true, the filter will accept the log request.

Also it will add the log message into the ThreadLocal RequestContext if the logger starts with com.myapp.
Logback.xml
<turboFilter class="com.myapp.PerRequestTurboFilter">
 <Key>X-Debug-Request</Key>
 <OnHigherOrEqual>ACCEPT</OnHigherOrEqual>
 <OnLower>NEUTRAL</OnLower>
 <MDCValueLevelPair>
  <value>true</value>
  <level>DEBUG</level>
 </MDCValueLevelPair>
</turboFilter>

Jersey Filter
@Provider
@Component
public class HttpHeaderFilter implements ContainerRequestFilter, ContainerResponseFilter {

    public static final String X_DEBUG_REQUEST = "X-Debug-Request";
    private static final String X_DEBUG_KEY = "X-DEBUG-KEY";
    // Used to protect debug header, we can change it from property file.
    @Value("${debug.key:}")
    private String debugKey;

    @Context
    HttpServletRequest servletRequest;

    @Override
    public ContainerRequest filter(final ContainerRequest request) {
        setLogDiagnosticContextParams(request);
        return request;
    }

    private void setLogDiagnosticContextParams(final ContainerRequest request) {
        final String debugRequest = request.getHeaderValue(X_DEBUG_REQUEST);;
        if (debugRequest != null) {

            final String clientKey = request.getHeaderValue(X_DEBUG_KEY);
            if (debugKey.equals(clientKey)) {
                MDC.put(X_DEBUG_REQUEST, debugRequest);
                RequestContextUtil.getRequestContext().setEnableDebug(Boolean.valueOf(debugRequest));
            } else {
                RequestContextUtil.getRequestContext().setEnableDebug(false);
            }
        }
    }

    @Override
    public ContainerResponse filter(final ContainerRequest request, final ContainerResponse response) {
        final MultivaluedMap<String, Object> headers = response.getHttpHeaders();

        final Object entity = response.getEntity();
 if (RequestContextUtil.getRequestContext().isEnableDebug()) {
     if (entity instanceof ClientData) {
         final ClientData<?> clientData = (ClientData<?>) entity;
         clientData.add(ClientData.DIAGNOSIS, RequestContextUtil.getRequestContext().getDiagnosises());
     } else {
         headers.add(ClientData.DIAGNOSIS, RequestContextUtil.getRequestContext().getDiagnosises());
     }
 }
        clear();
        return response;
    }

    private void clear() {
        MDC.clear();
        RequestContextUtil.removeRequestContext();
    }
}

We can also add request-id, logged userinto MDC, and change log pattern to include them in logback.xml.

In code, we can add diagnosis info like: RequestContextUtil.getRequestContext().getDiagnosises().add(String.format("query: %s", query));

RequestContextUtil and RequestContext
public class RequestContextUtil {
    private static ThreadLocal<RequestContext> requestContextLocal = new ThreadLocal<RequestContext>() {
        protected RequestContext initialValue() {
            return new RequestContext();
        };
    };

    public static ThreadLocal<RequestContext> getRequestContextLocal() {
        return requestContextLocal;
    }

    public static void setRequestContext(final RequestContext userContext) {
        requestContextLocal.set(userContext);
    }

    public static RequestContext getRequestContext() {
        return requestContextLocal.get();
    }

    public static void removeRequestContext() {
        requestContextLocal.remove();
    }

    public static class RequestContext implements Serializable {
        private static final long serialVersionUID = 1L;

        private boolean enableDebug;
        final List<String> diagnosises = new ArrayList<>();

        public List<String> getDiagnosises() {
            return diagnosises;
        }

        public void addDiagnosis(final String diagnosis) {
            diagnosises.add(diagnosis);
        }

        public boolean isEnableDebug() {
            return enableDebug;
        }

        public void setEnableDebug(final boolean enableDebug) {
            this.enableDebug = enableDebug;
        }
    }
}

Other Approaches
  • Expose API to change log level dynamically and recover it later.
Misc
Debug Feature
Return debug info that can check from response without having to check the log
- Of course secured, protected

Mock User Feature
Preview Feature
In memory test users in test env

Labels

ANT (6) Algorithm (69) Algorithm Series (35) Android (7) Big Data (7) Blogger (14) Bugs (6) Cache (5) Chrome (19) Code Example (29) Code Quality (7) Coding Skills (5) Database (7) Debug (16) Design (5) Dev Tips (63) Eclipse (32) Git (5) Google (33) Guava (7) How to (9) Http Client (8) IDE (7) Interview (88) J2EE (13) J2SE (49) JSON (7) Java (186) JavaScript (27) Learning code (9) Lesson Learned (6) Linux (26) Lucene-Solr (112) Mac (10) Maven (8) Network (9) Nutch2 (18) Performance (9) PowerShell (11) Problem Solving (11) Programmer Skills (6) Scala (6) Security (9) Soft Skills (38) Spring (22) System Design (11) Testing (7) Text Mining (14) Tips (17) Tools (24) Troubleshooting (29) UIMA (9) Web Development (19) Windows (21) adsense (5) bat (8) regex (5) xml (5)