# Logging problem in production environment

**URL:** <https://www.ruby-forum.com/t/logging-problem-in-production-environment/84386>\
**Category:** Deployment\
**Created:** [February 3, 2007, 9:43pm UTC](https://www.ruby-forum.com/t/logging-problem-in-production-environment/84386 "2007-02-03T21:43:14Z")\
**Posts on this page:** 13\
**Page:** 1

<div class="post-metadata">

**Author:** ![wpwood](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/w/d6d6ee/32.png) [@wpwood](https://www.ruby-forum.com/u/wpwood)\
**Post date:** [February 3, 2007, 9:43pm UTC](https://www.ruby-forum.com/t/logging-problem-in-production-environment/84386/1 "2007-02-03T21:43:14Z")

</div>

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… 😉

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

---

<div class="post-metadata">

**Author:** ![wpwood](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/w/d6d6ee/32.png) [@wpwood](https://www.ruby-forum.com/u/wpwood)\
**Post date:** [February 4, 2007, 5:30am UTC](https://www.ruby-forum.com/t/logging-problem-in-production-environment/84386/2 "2007-02-04T05:30:49Z")

</div>

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. [removed\_email\_address@domain.invalid](mailto:removed_email_address@domain.invalid) 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… 😉
> 
> 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/](http://www.jeremymcanally.com/)

My free Ruby e-book:  
[http://www.humblelittlerubybook.com/book/](http://www.humblelittlerubybook.com/book/)

My blogs:

> **[Site not found · DreamHost](http://www.mrneighborly.com/)**
>
> The owner of this domain has not yet uploaded their website.

[http://www.rubyinpractice.com/](http://www.rubyinpractice.com/)

---

<div class="post-metadata">

**Author:** ![wpwood](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/w/d6d6ee/32.png) [@wpwood](https://www.ruby-forum.com/u/wpwood)\
**Post date:** [February 4, 2007, 10:56am UTC](https://www.ruby-forum.com/t/logging-problem-in-production-environment/84386/3 "2007-02-04T10:56:04Z")

</div>

> > 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… 😉
> > 
> > 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

---

<div class="post-metadata">

**Author:** ![wpwood](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/w/d6d6ee/32.png) [@wpwood](https://www.ruby-forum.com/u/wpwood)\
**Post date:** [February 4, 2007, 8:12pm UTC](https://www.ruby-forum.com/t/logging-problem-in-production-environment/84386/4 "2007-02-04T20:12:10Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![wpwood](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/w/d6d6ee/32.png) [@wpwood](https://www.ruby-forum.com/u/wpwood)\
**Post date:** [February 4, 2007, 8:33pm UTC](https://www.ruby-forum.com/t/logging-problem-in-production-environment/84386/5 "2007-02-04T20:33:12Z")

</div>

Hi Chad,

Chad F. wrote:

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

Gee, that’s good news 😉

> 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

---

<div class="post-metadata">

**Author:** ![wpwood](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/w/d6d6ee/32.png) [@wpwood](https://www.ruby-forum.com/u/wpwood)\
**Post date:** [February 4, 2007, 8:53pm UTC](https://www.ruby-forum.com/t/logging-problem-in-production-environment/84386/6 "2007-02-04T20:53:14Z")

</div>

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  
– removed\_email\_address@domain.invalid  
– Engine Y., Serious Rails Hosting  
– (866) 518-YARD (9273)

---

<div class="post-metadata">

**Author:** ![wpwood](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/w/d6d6ee/32.png) [@wpwood](https://www.ruby-forum.com/u/wpwood)\
**Post date:** [February 4, 2007, 9:34pm UTC](https://www.ruby-forum.com/t/logging-problem-in-production-environment/84386/7 "2007-02-04T21:34:18Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![wpwood](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/w/d6d6ee/32.png) [@wpwood](https://www.ruby-forum.com/u/wpwood)\
**Post date:** [February 4, 2007, 10:19pm UTC](https://www.ruby-forum.com/t/logging-problem-in-production-environment/84386/8 "2007-02-04T22:19:24Z")

</div>

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  
– removed\_email\_address@domain.invalid  
– Engine Y., Serious Rails Hosting  
– (866) 518-YARD (9273)

---

<div class="post-metadata">

**Author:** ![wpwood](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/w/d6d6ee/32.png) [@wpwood](https://www.ruby-forum.com/u/wpwood)\
**Post date:** [February 4, 2007, 10:25pm UTC](https://www.ruby-forum.com/t/logging-problem-in-production-environment/84386/9 "2007-02-04T22:25:25Z")

</div>

> 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

---

<div class="post-metadata">

**Author:** ![wpwood](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/w/d6d6ee/32.png) [@wpwood](https://www.ruby-forum.com/u/wpwood)\
**Post date:** [February 4, 2007, 11:05pm UTC](https://www.ruby-forum.com/t/logging-problem-in-production-environment/84386/10 "2007-02-04T23:05:26Z")

</div>

On 2/4/07, Bill W. [removed\_email\_address@domain.invalid](mailto:removed_email_address@domain.invalid) 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

---

<div class="post-metadata">

**Author:** ![wpwood](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/w/d6d6ee/32.png) [@wpwood](https://www.ruby-forum.com/u/wpwood)\
**Post date:** [February 4, 2007, 11:58pm UTC](https://www.ruby-forum.com/t/logging-problem-in-production-environment/84386/11 "2007-02-04T23:58:30Z")

</div>

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!  
😉

Thanks very much for your help. I appreciate it!

Best regards,  
Bill

---

<div class="post-metadata">

**Author:** ![wpwood](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/w/d6d6ee/32.png) [@wpwood](https://www.ruby-forum.com/u/wpwood)\
**Post date:** [February 5, 2007, 12:03am UTC](https://www.ruby-forum.com/t/logging-problem-in-production-environment/84386/12 "2007-02-05T00:03:30Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![wpwood](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/w/d6d6ee/32.png) [@wpwood](https://www.ruby-forum.com/u/wpwood)\
**Post date:** [February 5, 2007, 7:44am UTC](https://www.ruby-forum.com/t/logging-problem-in-production-environment/84386/13 "2007-02-05T07:44:52Z")

</div>

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