Logging problem in production environment

Rails Deployment
1

Please forgive the cross-post. I haven’t gotten any response on the
BackgrounDRb list and am hoping someone here will have some idea about
what the heck…

I’ve just moved a small but important piece of my app into the
production environment. The piece is using BackgrounDRb to do session
management. It appears that BackgrounDRb is writing to development.log
instead of production.log. The backgroundrb.yml file specifies
production, as does environment.rb. Mongel is writing to
production.log.

A little background (no pun intended ;-0 ) I’m using the ‘old’ version
of backgroundrb for session management. In the app, whenever a visitor
changes pages I record the time in a db record. In the worker, once a
second, I’m doing a find for that record. That find is getting logged
in development.log, not in production.log as I expected.

Can anybody tell me if my assumption that BackgrounDRb is doing this
logging is correct? Nothing is being written to backgroundrb.log.
What’s being written to development.log is a record of the SQL calls
being done in the worker which is why I assume that BackgrounDRb must be
doing the logging. But we all know about assumptions… :wink:

Anybody got any idea what I’ve done wrong? I’m out of ideas: good, bad,
or otherwise. Any insights, pointers, etc. are most sincerely
appreciated!

Thanks!
Bill

2

How are you doing the logging exactly? Can we see a code snippet?

As something to try (I’m not sure this will work), but as an
experiment use RAILS_DEFAULT_LOGGER to log the information rather than
whatever you’re using now (e.g., RAILS_DEFAULT_LOGGER.info(“Blah!”)).

–Jeremy

On 2/3/07, Bill W. [email protected] wrote:

production.log. The backgroundrb.yml file specifies production, as does
written to development.log is a record of the SQL calls being done in the
worker which is why I assume that BackgrounDRb must be doing the
logging. But we all know about assumptions… :wink:

Anybody got any idea what I’ve done wrong? I’m out of ideas: good, bad, or
otherwise. Any insights, pointers, etc. are most sincerely appreciated!

Thanks!
Bill

–
http://www.jeremymcanally.com/

My free Ruby e-book:
http://www.humblelittlerubybook.com/book/

My blogs:

http://www.rubyinpractice.com/

3

appears that BackgrounDRb is writing to development.log instead of
is correct? Nothing is being written to backgroundrb.log. What’s being
written to development.log is a record of the SQL calls being done in the
worker which is why I assume that BackgrounDRb must be doing the
logging. But we all know about assumptions… :wink:

Anybody got any idea what I’ve done wrong? I’m out of ideas: good, bad, or
otherwise. Any insights, pointers, etc. are most sincerely appreciated!

Thanks!
Bill

Hi Bill,

It’s been a few months since I ran into this, so I can’t remember the
details, but I think your problem is actually much worse than just
logging. I believe BackgrounDrb is being started with RAILS_ENV set
to development, which means it would be hitting the wrong database,
etc. You might try logging RAILS_ENV to be sure.

I believe you can set :environment in your BackgrounDrb config to
override the default.

Chad

4

Hi Jeremy,

Jeremy McAnally wrote:

How are you doing the logging exactly?
Can we see a code snippet?

If you mean the code I’m using to do logging… I don’t have any. The
problem I’m experiencing is with the logging Rails does on it’s own.
Sorry
I wasn’t clear.

Thanks much for your reply!
Bill

5

Hi Chad,

Chad F. wrote:

I think your problem is actually much worse than
just logging.

Gee, that’s good news :wink:

I believe BackgrounDrb is being started with
RAILS_ENV set to development, which means
it would be hitting the wrong database, etc.

As I responded to Jeremy, it’s not BackgrounDRb logging that’s going
haywire. It’s the normal Rails logging.

I went to bed last night believing firmly that the problem I’m having
lay
with my hosted environment and comitted fully to figuring out how to
conclusively demonstrate that to them.

I woke this morning with a plan, but also realizing that I’d missed an
important step in my debugging efforts so far. Everything works fine on
my
development box in development mode. But I hadn’t tested the behavior
on my
development box in production mode.

There definitely appears to be a problem with Backgroundrb in production
mode.

I am seeing exactly the same behavior on my local machine that I’m
seeing
on my hosted environment. In development mode, everything gets written
to
development.log as it should. Requests, reponses, database activity.
In
production mode, the web server logging goes to
production.log. But the SQL logging, and not all of it, goes to the
development log.

You might try logging RAILS_ENV to be sure.

I was just thinking that I should try to log or display what environment
BackgrouDRb is running in. Like Mongrel displays on-screen when it
starts
(on my Windows XP dev box). Will RAILS_ENV tell me that?

I believe you can set :environment in your
BackgrounDrb config to override the default.

Absolutely right. I’ve got that set to production. I’ve got the
ENV[‘RAILS_ENV’] ||= ‘production’ line in environment.rb uncommented.
Yesterday, in the hosted environment, I went so far as to change the
defaults in the BackgrouDRb start script. No joy.

The problem I’m seeing looks like some kind of interaction thing where
BackgrounDRb is changing some setting that Rails depends on to determine
where to log what. What’s really giving me fits is understanding why /
how
some of the logging gets written to one file and some to the other.
And
even wierder is that only the portion of the database activity being
done in
the BackgrounDRb worker is getting logged at_all. The database writes
that are being done in the Rails controller are just disappearing
altogether! Does any of that ‘ring a bell’ re: your past experience?

If anyone is interested, I would be VERY happy to forward the applet.
It’s
trivial in terms of size.

Best regards,
Bill

6

Bill-

Have you tried starting backgroundrb after setting RAILS_ENV ? LIke :

$ RAILS_ENV=production script/backgroundrb/start

-Ezra

On Feb 4, 2007, at 11:32 AM, Bill W. wrote:

I believe BackgrounDrb is being started with

You might try logging RAILS_ENV to be sure.
Absolutely right. I’ve got that set to production. I’ve got the
other. And

Best regards,
Bill

– Ezra Z.
– Lead Rails Evangelist
– [email protected]
– Engine Y., Serious Rails Hosting
– (866) 518-YARD (9273)

7

Hi Ezra,

Ezra Z. wrote:

Have you tried starting backgroundrb after
setting RAILS_ENV ? LIke :

$ RAILS_ENV=production script/backgroundrb/start

No I haven’t. I did try starting Mongrel and then BackgrounDRb
(thinking
that that would ensure that RAILS_ENV would have a value) and then
stopping
/ starting Mongrel again. That didn’t help.

Given that I’m getting the exact same results on my WinXP box and my
hosted
environment, I’m working today on the WinXP box.

Earlier, I put a ‘puts’ in the start script to echo the
CONFIG[‘environment’] value.
puts “Environment: #{CONFIG[‘environment’]}”

That’s used in the start script as:

ActiveRecord::Base.establish_connection(YAML.load(ERB.new(IO.read("#{RAILS_ROOT}/#{CONFIG[‘database_yml’]}")).result)[CONFIG[‘environment’]])

It’s returning:
Environment: production

Eden Li suggested in an offlist reply to my BackgroundRb-devel post
yesterday that I do as you’ve suggested but I hadn’t done it yet because
RAILS_ENV doesn’t appear in the start script.

Since I’m working on the WinXP box today, I just dropped the following
into
the start script.
puts “RAILS_ENV: #{RAILS_ENV}”

It’s returning:
RAILS_ENV: development.

I assume that’s not good ;-p

I’m guessing I can use the command line you gave me to force things to
the
‘right’ state on the hosting account. Yes? What can I do on my WinXP
box?

Thanks!
Bill

8

Hi~

On Feb 4, 2007, at 12:33 PM, Bill W. wrote:

Since I’m working on the WinXP box today, I just dropped the
to the
‘right’ state on the hosting account. Yes? What can I do on my
WinXP box?

Thanks!
Bill

I’m sorry but I don’t have a clue as to how to set ENV vars on
windows. I know you can do it but you will have to google for window
cmd shell ENV vars and figure out how to set RAILS_ENV=production
before you start backgroundrb.

Cheers-
– Ezra Z.
– Lead Rails Evangelist
– [email protected]
– Engine Y., Serious Rails Hosting
– (866) 518-YARD (9273)

9

Ezra Z. wrote:

Have you tried starting backgroundrb after
setting RAILS_ENV ? LIke :

$ RAILS_ENV=production script/backgroundrb/start

I can’t use this syntax on my WinXP box. So I put the following line in
start.rb right under the last ‘require’.
RAILS_ENV = ‘production’

The good news is that Rails is no longer logging the database activity
to
development.log

The not-quite-so-good news is that now Rails is not logging the database
activity at all.

Any ideas?

Thanks!
Bill

10

On 2/4/07, Bill W. [email protected] wrote:

RAILS_ENV = ‘production’

The good news is that Rails is no longer logging the database activity to
development.log

The not-quite-so-good news is that now Rails is not logging the database
activity at all.

Any ideas?

Rails doesn’t log database activity in production mode. This is
configured via the log level. If you have a problem you’re trying to
debug, you can turn on verbose logging with:

config.log_level = :debug

in production.rb. I wouldn’t leave it that way, though.

Chad

11

Hi Chad,

Chad F. wrote:

Rails doesn’t log database activity in production
mode.

There’s nothing quite so frustrating as not knowing when you’re done!
:wink:

Thanks very much for your help. I appreciate it!

Best regards,
Bill

12

Hi Ezra,

Ezra Z. wrote:

I’m sorry but I don’t have a clue as to how to
set ENV vars on windows.

I didn’t realize it was just an system environment variable. Sorry
about
that. I’ll write up a little thing and put it on the SF repository or
send
it to you, whichever is better. The applet is working on both the
Windows
and Linux environments now. Thanks very much for your help. I really
appreciate it!

I guess I can go watch the game now!

Best regards to all, and thanks again for the help!
Bill

13

You can set an environment variable using “set” e.g. set
RAILS_ENV=production. Don’t use quotes. Just typing in set will return
all the environment variables there.

Vish