Home

Wrong I18n key was read from memcached, when using unicorn

Recently I got a error from my project, which reported by hoptoad, the error information like:
I18n::MissingInterpolationArgument: missing interpolation argument in "I ran %{distance}km on %{date}. It took %{time}" ({:pace=>"..."} given)
You will find I was passing the data  {:pace=>"..."} to the translation key: "I ran %{distance}km on %{date}. It took %{time}".  this translation key required 3 parameters, but I only given one. And when I look into the code, I found there is no such a mistake as I mentioned above. Then I gave up to fix this problem. Couple of weeks past, one day, when I was driving back from shanghai to hangzhou, I overheard my colleagues was discussing about this issue, they found this problem is referred to some multi-process issue. Thereafter, I did a more deeper investigation, then finally found the reason and knew how to recur it.

How to recur it?

  1. memcached -vv
  2. watch lsof -i :11211
  3. unicorn -c config/unicorn.conf.rb -E production
  4. ab -n 1000 -c 100 http://localhost:8080 (You have to run this code as soon as possible after ran unicorn command.)
  5. tail -f log/production.log | grep ActionView::Template::Error
Then you would see some error messages in production.log which is the same to message wroten above.

What's the cause?

If you look carefully, when you start unicorn server, all the unicorn workers are using the same memcached connection.
memcached 11700 michaelhe   30u  IPv6 0xffffff800bbe3600      0t0  TCP localhost:11211->localhost:59310 (ESTABLISHED)
ruby      19672 michaelhe   10u  IPv6 0xffffff800bbe3910      0t0  TCP localhost:59310->localhost:11211 (ESTABLISHED)
ruby      19719 michaelhe   10u  IPv6 0xffffff800bbe3910      0t0  TCP localhost:59310->localhost:11211 (ESTABLISHED)
ruby      19720 michaelhe   10u  IPv6 0xffffff800bbe3910      0t0  TCP localhost:59310->localhost:11211 (ESTABLISHED)
ruby      19721 michaelhe   10u  IPv6 0xffffff800bbe3910      0t0  TCP localhost:59310->localhost:11211 (ESTABLISHED)
ruby      19722 michaelhe   10u  IPv6 0xffffff800bbe3910      0t0  TCP localhost:59310->localhost:11211 (ESTABLISHED)
ruby      19723 michaelhe   10u  IPv6 0xffffff800bbe3910      0t0  TCP localhost:59310->localhost:11211 (ESTABLISHED)
ruby      19724 michaelhe   10u  IPv6 0xffffff800bbe3910      0t0  TCP localhost:59310->localhost:11211 (ESTABLISHED)
ruby      19725 michaelhe   10u  IPv6 0xffffff800bbe3910      0t0  TCP localhost:59310->localhost:11211 (ESTABLISHED)
ruby      19726 michaelhe   10u  IPv6 0xffffff800bbe3910      0t0  TCP localhost:59310->localhost:11211 (ESTABLISHED)
Then 2 http requests come, they are processed by 2 unicorn processes, then request A send many "get" requests to memcached, as well as request B. but they are using the same memcached connection at beginning, so in extreme condition, request B will get the values which is respond for the request send from request A, whereafter the tragedy happened.   However, after several errors was raised, everything goes well, no error was raised for all the time. I notice one thing:
memcached 11700 michaelhe   30u  IPv6 0xffffff800bbe3600      0t0  TCP localhost:11211->localhost:59310 (ESTABLISHED)
memcached 11700 michaelhe   31u  IPv6 0xffffff800f2b7140      0t0  TCP localhost:11211->localhost:59979 (ESTABLISHED)
memcached 11700 michaelhe   32u  IPv6 0xffffff800bbe54a0      0t0  TCP localhost:11211->localhost:59980 (ESTABLISHED)
memcached 11700 michaelhe   33u  IPv6 0xffffff800f2b7d80      0t0  TCP localhost:11211->localhost:59984 (ESTABLISHED)
memcached 11700 michaelhe   34u  IPv6 0xffffff800f2b83a0      0t0  TCP localhost:11211->localhost:59986 (ESTABLISHED)
memcached 11700 michaelhe   35u  IPv6 0xffffff800f2bfb70      0t0  TCP localhost:11211->localhost:59987 (ESTABLISHED)
memcached 11700 michaelhe   36u  IPv6 0xffffff800f2c0dd0      0t0  TCP localhost:11211->localhost:59991 (ESTABLISHED)
memcached 11700 michaelhe   37u  IPv6 0xffffff800f2b7450      0t0  TCP localhost:11211->localhost:59994 (ESTABLISHED)
ruby      19672 michaelhe   10u  IPv6 0xffffff800bbe3910      0t0  TCP localhost:59310->localhost:11211 (ESTABLISHED)
ruby      19719 michaelhe   10u  IPv6 0xffffff800f2b8cd0      0t0  TCP localhost:59984->localhost:11211 (ESTABLISHED)
ruby      19720 michaelhe   11u  IPv6 0xffffff800bbe3f30      0t0  TCP localhost:59986->localhost:11211 (ESTABLISHED)
ruby      19721 michaelhe   10u  IPv6 0xffffff800f2b7a70      0t0  TCP localhost:59979->localhost:11211 (ESTABLISHED)
ruby      19722 michaelhe   10u  IPv6 0xffffff800bbe4550      0t0  TCP localhost:59987->localhost:11211 (ESTABLISHED)
ruby      19723 michaelhe   10u  IPv6 0xffffff800f2bef30      0t0  TCP localhost:59991->localhost:11211 (ESTABLISHED)
ruby      19724 michaelhe   10u  IPv6 0xffffff800f2bec20      0t0  TCP localhost:59980->localhost:11211 (ESTABLISHED)
ruby      19725 michaelhe   10u  IPv6 0xffffff800bbe3910      0t0  TCP localhost:59310->localhost:11211 (ESTABLISHED)
ruby      19726 michaelhe   10u  IPv6 0xffffff800f2bf860      0t0  TCP localhost:59994->localhost:11211 (ESTABLISHED)
The connections to memcached of each unicorn worker was reset, each worker has its own connection, so that's why it goes correctly.

How to solve it?

After a little research online, I found the comments in unicorn config file:
after_fork do |server, worker|
  ##
  # Unicorn master loads the app then forks off workers - because of the way
  # Unix forking works, we need to make sure we aren't using any of the parent's
  # sockets, e.g. db connection
Yes, the magic code to fix this problem is:
Rails.cache.reset
I18n.cache_store.reset
add them into the after_fork block in unicorn config file. And what happened then?
memcached 11700 michaelhe   30u  IPv6 0xffffff800f2b7140      0t0  TCP localhost:11211->localhost:60687 (ESTABLISHED)
ruby      24046 michaelhe   10u  IPv6 0xffffff800bbe3600      0t0  TCP localhost:60687->localhost:11211 (ESTABLISHED)
Any other unicorn workers won't use the connection of unicorn master, instead, they will generate a new connection when on demand.
BTW,  this bug happen to both ruby 1.8.7 and REE.

The Scrum methods that I want to try in the real dev life

Backlog => Sprint => Burndown => Demo => ...(Repeat)

 

What should I do after get the new feature to implement?

Generally we would get a ticket from leader (scrum master), then do it. before do it. But what should we do before start to do it:
  1. We will go to understand the requirement first.
  2. Make a "Accpetance test story" which must be wrote as simple and direct as possible, that client can see what you will do and confirm your understanding.
  3. Seperate this big requirement into many small tickets, the best size is can be finished in one day. --- It will be easy for ScrumMaster to trace your progress and it would be more explicit about what to do in this ticket.
(Notice, don't make the tickets too small, for avoiding micro-management which is not cost-efficient.)

Have the chance to be leader.

Let all scrum members have the feeling of they are the manager of their task, but manager will be happier when they have resources to manage not only themselves, like
  1. They have people to assign sub-tasks to.
  2. They can make decision in their job.
  3. They can make schedule for their tasks.
So it will be good method for solving this issue. Do more pair programming, for each story, one of two members can be the leader to lead other one to finish this tasks.

Ticket title or content should be none or less technical words.

Let client knows the time spent on it is worth it. You will be more comfirtable to do it.

Use Burndown chart to monitor the productivity.

This is the best way to know the health condition of the team.

Get all team members around when you do estimating.

It will be more accurate and know more about what is included in the tasks, let them estimate but not promise.

Team members should be *together*.

Together means they can Hear and See each other, also better to be seperated from other teams, that won't affect other team's work.

Give more time on quality, it worth it.

It's not about developer don't want to have a high quality work, it's about schedule made by leader didn't give them the chance.

Do retrospect after each sprint.

This will make team more health, keep a high performance and high quality work, more effective than overtime working :) Questions would be:
  • Anything to improvement?
  • Any problem you've found?
  • Any new tech can be applied into project?

Have a break between two sprints!

This could be a good award to the team members who finish sprint in time. You just come to company do whatever that you do want to:
  • Study new technology.
  • Discussing anything with team members.
  • Coffee
  • Feet on desk
Maybe 1 day, half day, or hold a company party after work hours, or in the weekend company can offer a small trip for team members.

[video]A crazy team: Just a bunch of factory worker made a fancy "Megatron".

They are just a bunch of factory workers, but depend on their enthusiasm, did a great work by their mere knowledge, information and a pile of junk.

Why are you leaving your company?

Why are you leaving your company?
I am always trying to understand why people leaving their job, although they got good salary and in a good company.
Here I collect some reason for people leaving previous company:
  • I found myself bored with the work and looking for more challenges. I am an excellent employee and I didn't want my unhappiness to have any impact on the job I was doing for my employer.
  • There isn't room for growth with my current employer and I'm ready to move on to a new challenge.
  • I'm looking for a bigger challenge and to grow my career and I couldn't job hunt part time while working. It didn't seem ethical to use my former employer's time.
  • I've decided that is not the direction I want to go in my career and my current employer has no opportunities in the direction I'd like to head.
  • After several years in my last position, I'm looking for an company where I can contribute and grow in a team-oriented environment.
  • I am interested in a new challenge and an opportunity to use my technical skills and experience in a different capacity than I have in the past.
  • I recently received my degree and I want to utilize my educational background in my next position.
  • I am interested in a job with more responsibility, and I am very ready for a new challenge.
  • I left my last position in order to spend more time with my family. Circumstances have changed and I'm more than ready for full-time employment again.
  • I am seeking a position with a stable company with room for growth and opportunity for advancement.
  • I was commuting to the city and spending a significant amount of time each day on travel. I would prefer to be closer to home.
  • To be honest, I wasn't considering a move, but, I saw this job posting and was intrigued by the position and the company. It sounds like an exciting opportunity and an ideal match with my qualifications.
  • This position seemed like an excellent match for my skills and experience and I am not able to fully utilize them in my present job.
  • The company was cutting back and, unfortunately, my job was one of those eliminated.
Didn't be cared, like he didn't been put at a important position, or just like a dust man in the project. Didn't feel he is important. Didn't get the agreement from boss or leader. Didn't feel they have enough room for growth. Didn't feel a team belonging feeling. Didn't increase salary for a long time.

List files under specified path by using find command

find /path/to/find -type f -iname *.jpg -o -iname *.css