Zero downtime Spree

bluepill.log

I, [2013-05-02T18:08:41.746041 #9206]  INFO -- : [spree:unicorn:unicorn:<child(pid:9278)>] mem_usage: [131MB, 131MB, 131MB, 131MB]

D, [2013-05-02T18:08:45.631469 #9206] DEBUG -- : [spree] pid journal PWD=/
D, [2013-05-02T18:08:45.631872 #9206] DEBUG -- : [spree] pid journal = 9263 9266 9269 9272 9275 9278
D, [2013-05-02T18:08:45.632242 #9206] DEBUG -- : [spree] Acquired lock .bluepill_pids_journal.unicorn.lock
I, [2013-05-02T18:08:45.732892 #9206]  INFO -- : [spree] Termed old process 9263
I, [2013-05-02T18:08:45.833462 #9206]  INFO -- : [spree] Termed old process 9266
I, [2013-05-02T18:08:45.934047 #9206]  INFO -- : [spree] Termed old process 9269
I, [2013-05-02T18:08:46.034605 #9206]  INFO -- : [spree] Termed old process 9272
I, [2013-05-02T18:08:46.135164 #9206]  INFO -- : [spree] Termed old process 9275
I, [2013-05-02T18:08:46.235871 #9206]  INFO -- : [spree] Termed old process 9278
D, [2013-05-02T18:08:47.737825 #9206] DEBUG -- : [spree] Unable to kill missing process 9263
D, [2013-05-02T18:08:47.738207 #9206] DEBUG -- : [spree] Unable to kill missing process 9266
D, [2013-05-02T18:08:47.738627 #9206] DEBUG -- : [spree] Unable to kill missing process 9269
D, [2013-05-02T18:08:47.738872 #9206] DEBUG -- : [spree] Unable to kill missing process 9272
D, [2013-05-02T18:08:47.739110 #9206] DEBUG -- : [spree] Unable to kill missing process 9275
D, [2013-05-02T18:08:47.739437 #9206] DEBUG -- : [spree] Unable to kill missing process 9278
D, [2013-05-02T18:08:47.739682 #9206] DEBUG -- : [spree] Journal cleanup completed
D, [2013-05-02T18:08:47.739929 #9206] DEBUG -- : [spree] Cleared lock .bluepill_pids_journal.unicorn.lock
D, [2013-05-02T18:08:47.740088 #9206] DEBUG -- : [spree] pgid journal PWD=/
D, [2013-05-02T18:08:47.740368 #9206] DEBUG -- : [spree] pgid journal = 9255
D, [2013-05-02T18:08:47.740672 #9206] DEBUG -- : [spree] Acquired lock .bluepill_pgids_journal.unicorn.lock
I, [2013-05-02T18:08:47.841077 #9206]  INFO -- : [spree] Termed old process group 9255
D, [2013-05-02T18:08:47.841505 #9206] DEBUG -- : [spree] Journal cleanup completed
D, [2013-05-02T18:08:47.841695 #9206] DEBUG -- : [spree] Cleared lock .bluepill_pgids_journal.unicorn.lock
E, [2013-05-02T18:08:47.842160 #9206] ERROR -- : [spree:unicorn:unicorn:<child(pid:9275)>] Failed to signal process 9275 with code 0: No such process
E, [2013-05-02T18:08:47.842459 #9206] ERROR -- : [spree:unicorn:unicorn:<child(pid:9278)>] Failed to signal process 9278 with code 0: No such process
I, [2013-05-02T18:08:47.854819 #9206]  INFO -- : [spree:unicorn:unicorn] Existing children: 9263,9266,9269,9272. Got new children: [6284, 6287] for 9258
D, [2013-05-02T18:08:47.855152 #9206] DEBUG -- : [spree] Acquired lock .bluepill_pgids_journal.unicorn.lock
D, [2013-05-02T18:08:47.855282 #9206] DEBUG -- : [spree] pgid journal PWD=/
D, [2013-05-02T18:08:47.868717 #9206] DEBUG -- : [spree] Saving pgid 9255 to process journal unicorn
I, [2013-05-02T18:08:47.869230 #9206]  INFO -- : [spree] Saved pgid 9255 to journal unicorn
D, [2013-05-02T18:08:47.869380 #9206] DEBUG -- : [spree] Journal now = 9255

D, [2013-05-02T18:08:47.869541 #9206] DEBUG -- : [spree] Cleared lock .bluepill_pgids_journal.unicorn.lock
D, [2013-05-02T18:08:47.869706 #9206] DEBUG -- : [spree] Acquired lock .bluepill_pids_journal.unicorn.lock
D, [2013-05-02T18:08:47.869815 #9206] DEBUG -- : [spree] pid journal PWD=/
D, [2013-05-02T18:08:47.870004 #9206] DEBUG -- : [spree] Saving pid 6284 to process journal unicorn
I, [2013-05-02T18:08:47.870185 #9206]  INFO -- : [spree] Saved pid 6284 to journal unicorn
D, [2013-05-02T18:08:47.870312 #9206] DEBUG -- : [spree] Journal now = 6284

D, [2013-05-02T18:08:47.870453 #9206] DEBUG -- : [spree] Cleared lock .bluepill_pids_journal.unicorn.lock
D, [2013-05-02T18:08:47.971395 #9206] DEBUG -- : [spree] Acquired lock .bluepill_pgids_journal.unicorn.lock
D, [2013-05-02T18:08:47.971652 #9206] DEBUG -- : [spree] pgid journal PWD=/
D, [2013-05-02T18:08:47.971807 #9206] DEBUG -- : [spree] pgid journal = 9255
D, [2013-05-02T18:08:47.971915 #9206] DEBUG -- : [spree] Skipping duplicate pgid 9255 already in journal unicorn
D, [2013-05-02T18:08:47.972086 #9206] DEBUG -- : [spree] Cleared lock .bluepill_pgids_journal.unicorn.lock
D, [2013-05-02T18:08:47.972253 #9206] DEBUG -- : [spree] Acquired lock .bluepill_pids_journal.unicorn.lock
D, [2013-05-02T18:08:47.972364 #9206] DEBUG -- : [spree] pid journal PWD=/
D, [2013-05-02T18:08:47.972508 #9206] DEBUG -- : [spree] pid journal = 6284
D, [2013-05-02T18:08:47.972614 #9206] DEBUG -- : [spree] Saving pid 6287 to process journal unicorn
I, [2013-05-02T18:08:47.972768 #9206]  INFO -- : [spree] Saved pid 6287 to journal unicorn
D, [2013-05-02T18:08:47.972951 #9206] DEBUG -- : [spree] Journal now = 6284
6287

D, [2013-05-02T18:08:47.973094 #9206] DEBUG -- : [spree] Cleared lock .bluepill_pids_journal.unicorn.lock
E, [2013-05-02T18:08:48.074341 #9206] ERROR -- : [spree:unicorn:unicorn:<child(pid:9263)>] Failed to signal process 9263 with code 0: No such process
E, [2013-05-02T18:08:48.074708 #9206] ERROR -- : [spree:unicorn:unicorn:<child(pid:9263)>] Failed to signal process  with code 0: no implicit conversion from nil to integer
I, [2013-05-02T18:08:48.075148 #9206]  INFO -- : [spree:unicorn:unicorn:<child(pid:9263)>] Going from up => down
E, [2013-05-02T18:08:48.075530 #9206] ERROR -- : [spree:unicorn:unicorn:<child(pid:9266)>] Failed to signal process 9266 with code 0: No such process
E, [2013-05-02T18:08:48.075811 #9206] ERROR -- : [spree:unicorn:unicorn:<child(pid:9266)>] Failed to signal process  with code 0: no implicit conversion from nil to integer
I, [2013-05-02T18:08:48.076158 #9206]  INFO -- : [spree:unicorn:unicorn:<child(pid:9266)>] Going from up => down
E, [2013-05-02T18:08:48.076552 #9206] ERROR -- : [spree:unicorn:unicorn:<child(pid:9269)>] Failed to signal process 9269 with code 0: No such process
E, [2013-05-02T18:08:48.076870 #9206] ERROR -- : [spree:unicorn:unicorn:<child(pid:9269)>] Failed to signal process  with code 0: no implicit conversion from nil to integer
I, [2013-05-02T18:08:48.077220 #9206]  INFO -- : [spree:unicorn:unicorn:<child(pid:9269)>] Going from up => down
E, [2013-05-02T18:08:48.077572 #9206] ERROR -- : [spree:unicorn:unicorn:<child(pid:9272)>] Failed to signal process 9272 with code 0: No such process
E, [2013-05-02T18:08:48.077796 #9206] ERROR -- : [spree:unicorn:unicorn:<child(pid:9272)>] Failed to signal process  with code 0: no implicit conversion from nil to integer
I, [2013-05-02T18:08:48.078127 #9206]  INFO -- : [spree:unicorn:unicorn:<child(pid:9272)>] Going from up => down
I, [2013-05-02T18:08:48.179562 #9206]  INFO -- : [spree:unicorn:unicorn:<child(pid:6284)>] mem_usage: [0KB]

I, [2013-05-02T18:08:48.180015 #9206]  INFO -- : [spree:unicorn:unicorn:<child(pid:6284)>] cpu_usage: [31.0*]

I, [2013-05-02T18:08:48.281193 #9206]  INFO -- : [spree:unicorn:unicorn:<child(pid:6287)>] mem_usage: [108MB]

I, [2013-05-02T18:08:48.281418 #9206]  INFO -- : [spree:unicorn:unicorn:<child(pid:6287)>] cpu_usage: [0.0]

I, [2013-05-02T18:08:49.903675 #6302]  INFO -- : [spree:unicorn:unicorn] Existing children: . Got new children: [6284, 6287, 6296, 6305] for 9258
D, [2013-05-02T18:08:49.904552 #6302] DEBUG -- : [spree] Acquired lock .bluepill_pgids_journal.unicorn.lock
D, [2013-05-02T18:08:49.904895 #6302] DEBUG -- : [spree] pgid journal PWD=/
D, [2013-05-02T18:08:49.905353 #6302] DEBUG -- : [spree] pgid journal = 9255
D, [2013-05-02T18:08:49.905613 #6302] DEBUG -- : [spree] Skipping duplicate pgid 9255 already in journal unicorn
D, [2013-05-02T18:08:49.905959 #6302] DEBUG -- : [spree] Cleared lock .bluepill_pgids_journal.unicorn.lock
D, [2013-05-02T18:08:49.906269 #6302] DEBUG -- : [spree] Acquired lock .bluepill_pids_journal.unicorn.lock
D, [2013-05-02T18:08:49.906539 #6302] DEBUG -- : [spree] pid journal PWD=/
D, [2013-05-02T18:08:49.906906 #6302] DEBUG -- : [spree] pid journal = 6284 6287
D, [2013-05-02T18:08:49.907158 #6302] DEBUG -- : [spree] Skipping duplicate pid 6284 already in journal unicorn
D, [2013-05-02T18:08:49.907479 #6302] DEBUG -- : [spree] Cleared lock .bluepill_pids_journal.unicorn.lock
D, [2013-05-02T18:08:50.009280 #6302] DEBUG -- : [spree] Acquired lock .bluepill_pgids_journal.unicorn.lock
D, [2013-05-02T18:08:50.009827 #6302] DEBUG -- : [spree] pgid journal PWD=/
D, [2013-05-02T18:08:50.010208 #6302] DEBUG -- : [spree] pgid journal = 9255
D, [2013-05-02T18:08:50.010469 #6302] DEBUG -- : [spree] Skipping duplicate pgid 9255 already in journal unicorn
D, [2013-05-02T18:08:50.010852 #6302] DEBUG -- : [spree] Cleared lock .bluepill_pgids_journal.unicorn.lock
D, [2013-05-02T18:08:50.011229 #6302] DEBUG -- : [spree] Acquired lock .bluepill_pids_journal.unicorn.lock
D, [2013-05-02T18:08:50.011479 #6302] DEBUG -- : [spree] pid journal PWD=/
D, [2013-05-02T18:08:50.011889 #6302] DEBUG -- : [spree] pid journal = 6284 6287
D, [2013-05-02T18:08:50.012145 #6302] DEBUG -- : [spree] Skipping duplicate pid 6287 already in journal unicorn
D, [2013-05-02T18:08:50.012446 #6302] DEBUG -- : [spree] Cleared lock .bluepill_pids_journal.unicorn.lock
D, [2013-05-02T18:08:50.113971 #6302] DEBUG -- : [spree] Acquired lock .bluepill_pgids_journal.unicorn.lock
D, [2013-05-02T18:08:50.114457 #6302] DEBUG -- : [spree] pgid journal PWD=/
D, [2013-05-02T18:08:50.114881 #6302] DEBUG -- : [spree] pgid journal = 9255
D, [2013-05-02T18:08:50.115141 #6302] DEBUG -- : [spree] Skipping duplicate pgid 9255 already in journal unicorn
D, [2013-05-02T18:08:50.115490 #6302] DEBUG -- : [spree] Cleared lock .bluepill_pgids_journal.unicorn.lock
D, [2013-05-02T18:08:50.115941 #6302] DEBUG -- : [spree] Acquired lock .bluepill_pids_journal.unicorn.lock
D, [2013-05-02T18:08:50.116207 #6302] DEBUG -- : [spree] pid journal PWD=/
D, [2013-05-02T18:08:50.116512 #6302] DEBUG -- : [spree] pid journal = 6284 6287
D, [2013-05-02T18:08:50.116880 #6302] DEBUG -- : [spree] Saving pid 6296 to process journal unicorn
I, [2013-05-02T18:08:50.117264 #6302]  INFO -- : [spree] Saved pid 6296 to journal unicorn
D, [2013-05-02T18:08:50.117572 #6302] DEBUG -- : [spree] Journal now = 6284
6287
6296

D, [2013-05-02T18:08:50.117989 #6302] DEBUG -- : [spree] Cleared lock .bluepill_pids_journal.unicorn.lock
D, [2013-05-02T18:08:50.219300 #6302] DEBUG -- : [spree] Acquired lock .bluepill_pgids_journal.unicorn.lock
D, [2013-05-02T18:08:50.219788 #6302] DEBUG -- : [spree] pgid journal PWD=/
D, [2013-05-02T18:08:50.220102 #6302] DEBUG -- : [spree] pgid journal = 9255
D, [2013-05-02T18:08:50.220397 #6302] DEBUG -- : [spree] Skipping duplicate pgid 9255 already in journal unicorn
D, [2013-05-02T18:08:50.220725 #6302] DEBUG -- : [spree] Cleared lock .bluepill_pgids_journal.unicorn.lock
D, [2013-05-02T18:08:50.221162 #6302] DEBUG -- : [spree] Acquired lock .bluepill_pids_journal.unicorn.lock
D, [2013-05-02T18:08:50.221424 #6302] DEBUG -- : [spree] pid journal PWD=/
D, [2013-05-02T18:08:50.221759 #6302] DEBUG -- : [spree] pid journal = 6284 6287 6296
D, [2013-05-02T18:08:50.222072 #6302] DEBUG -- : [spree] Saving pid 6305 to process journal unicorn
I, [2013-05-02T18:08:50.222386 #6302]  INFO -- : [spree] Saved pid 6305 to journal unicorn
D, [2013-05-02T18:08:50.222646 #6302] DEBUG -- : [spree] Journal now = 6284
6287
6296
6305

D, [2013-05-02T18:08:50.222944 #6302] DEBUG -- : [spree] Cleared lock .bluepill_pids_journal.unicorn.lock
I, [2013-05-02T18:08:50.439757 #6302]  INFO -- : [spree:unicorn:unicorn:<child(pid:6284)>] mem_usage: [0KB]

I, [2013-05-02T18:08:50.440236 #6302]  INFO -- : [spree:unicorn:unicorn:<child(pid:6284)>] cpu_usage: [10.3]

I, [2013-05-02T18:08:50.542140 #6302]  INFO -- : [spree:unicorn:unicorn:<child(pid:6287)>] cpu_usage: [13.5]

I, [2013-05-02T18:08:50.542648 #6302]  INFO -- : [spree:unicorn:unicorn:<child(pid:6287)>] mem_usage: [0KB]

I, [2013-05-02T18:08:50.644416 #6302]  INFO -- : [spree:unicorn:unicorn:<child(pid:6296)>] mem_usage: [0KB]

I, [2013-05-02T18:08:50.644974 #6302]  INFO -- : [spree:unicorn:unicorn:<child(pid:6296)>] cpu_usage: [0.0]

I, [2013-05-02T18:08:50.747403 #6302]  INFO -- : [spree:unicorn:unicorn:<child(pid:6305)>] mem_usage: [0KB]

I, [2013-05-02T18:08:50.747739 #6302]  INFO -- : [spree:unicorn:unicorn:<child(pid:6305)>] cpu_usage: [0.0]

W, [2013-05-02T18:08:50.749623 #6302]  WARN -- : [spree:unicorn:unicorn] Executing restart command: kill -USR2 9258

gistfile1.txt

-

unicorn.stderr.log

I, [2013-05-02T19:08:59.284730 #25596]  INFO -- : reaped #<Process::Status: pid 25601 exit 0> worker=0
I, [2013-05-02T19:09:00.290893 #25596]  INFO -- : reaped #<Process::Status: pid 25604 exit 0> worker=1
I, [2013-05-02T19:09:00.291235 #25596]  INFO -- : reaped #<Process::Status: pid 25607 exit 0> worker=2
I, [2013-05-02T19:09:00.291388 #25596]  INFO -- : reaped #<Process::Status: pid 25610 exit 0> worker=3
I, [2013-05-02T19:09:00.291607 #25596]  INFO -- : reaped #<Process::Status: pid 25613 exit 0> worker=4
I, [2013-05-02T19:09:00.291775 #25596]  INFO -- : reaped #<Process::Status: pid 25616 exit 0> worker=5
I, [2013-05-02T19:09:00.580257 #29515]  INFO -- : worker=0 ready
I, [2013-05-02T19:09:05.319663 #25596]  INFO -- : reaped #<Process::Status: pid 29515 exit 0> worker=0
I, [2013-05-02T19:09:05.320032 #25596]  INFO -- : reaped #<Process::Status: pid 29519 exit 0> worker=1
I, [2013-05-02T19:09:05.320177 #25596]  INFO -- : reaped #<Process::Status: pid 29535 exit 0> worker=2
I, [2013-05-02T19:09:05.320315 #25596]  INFO -- : reaped #<Process::Status: pid 29555 exit 0> worker=3
I, [2013-05-02T19:09:05.320432 #25596]  INFO -- : reaped #<Process::Status: pid 29558 exit 0> worker=4
I, [2013-05-02T19:09:05.421406 #25596]  INFO -- : reaped #<Process::Status: pid 29561 exit 0> worker=5
I, [2013-05-02T19:09:05.421973 #25596]  INFO -- : master complete
I, [2013-05-02T19:10:04.854202 #29588]  INFO -- : Refreshing Gem list
I, [2013-05-02T19:10:26.041767 #29588]  INFO -- : unlinking existing socket=/data/spree/shared/sockets/unicorn.sock
I, [2013-05-02T19:10:26.042002 #29588]  INFO -- : listening on addr=/data/spree/shared/sockets/unicorn.sock fd=17
I, [2013-05-02T19:10:27.075830 #29597]  INFO -- : worker=0 ready
I, [2013-05-02T19:10:28.084503 #29601]  INFO -- : worker=1 ready
I, [2013-05-02T19:10:29.071748 #29604]  INFO -- : worker=2 ready
I, [2013-05-02T19:10:30.090571 #29608]  INFO -- : worker=3 ready
I, [2013-05-02T19:10:31.080098 #29611]  INFO -- : worker=4 ready
I, [2013-05-02T19:10:32.069540 #29588]  INFO -- : master process ready
I, [2013-05-02T19:10:32.086882 #29618]  INFO -- : worker=5 ready