print is atomic instead of mutex so it works in threaded environs

[reidmix]

When using multiple threads we are running into a scenario using SideKiq/SideTiq where the mutex in Scrolls::Log#write isn't doing what we expect. Even with the mutex, it is not shared across threads, and in the following example, the two loglines are not being separated out with a newline as we'd expect:

2014-09-18T04:57:00.897495+00:00 54.80.127.117 local7.info app[worker.1]: - d.fdd8e8d0-048c-4667-9199-218114219753 sample#app.q.enqueued=0 sample#app.q.processed=1 sample#watchtower.q.failed=0 measure#app.q.latency=02014-09-18T04:57:00.897Z 2 TID-owg6kvhpo INFO: [Sidetiq] Enqueue: Stats (at: 1411016280.0) (last: 1411016220.0)

To simplify the case, we can see that puts is not atomic:

1.9.3-p448 :015 >   10.times { Thread.new { puts "hi" }}
 => 10 
1.9.3-p448 :016 > hihihihi
hi

hihi

hi
hihi

A solution is to use print, it is atomic and works as expected (even without the mutex):

1.9.3-p448 :016 > 10.times { Thread.new { print "hi\n" }}
hi
hi
hi
 => 10 
hi
hi
hi
hi
hi
hi

Additionally, removing the rescue that was an artifact from an old refactor: https://github.com/asenchi/scrolls/commit/60e7220341cd02de006991d35934b1bd7f6f3cd2

[reidmix]

Tagging: @dickeyxxx who worked on this fix with me, @pedro who determined the solution to this bug, and @amerine who reported this issue

[jdx]

In a situation using multiple processes or a setup like sidekiq that wouldn't share the mutex, you could see this come up. It would generally be very rare since it would be 2 different threads/processes running puts at the same time.

I think we might be seeing it since we're running 2 schedulers (which is an issue by itself, I'll admit), but performing the log atomically vs a mutex I think is a better solution to the problem anyways.

[eric]

:+1:

[amacneil]

:+1:

We have also been seeing this for months (see #64)

[mikehale]

:+1:

[asenchi]

Not sure why I never received any of these emails.

Regardless this seems pretty straight forward.

[jmervine]

Mind updating @reidmix and I when when this is released?

[dbussink]

Looks like this broke using syslog, since the syslog class only has a puts method: https://github.com/asenchi/scrolls/blob/master/lib/scrolls/syslog.rb#L38.

[asenchi]

Hello @dbussink Good call out. Looking at your PR as well. I'm picking things back up and hope to get the project cleaned up over the next week. Sorry for the lack of maintenance here.