librelist archives

« back to archive

log en rails 3

log en rails 3

From:
Franco Brusatti
Date:
2011-01-18 @ 19:30
Hola gente,

  tengo un inconveniente con los logs en una app en rails 3, el tema es que
veo un monton de notificaciones en el log (en modo desarrollo y producción
también), chequeando el archivo log/development.rb me doy cuenta que no se
estan grabando ahi pero se ven en la pantalla cuando una consulta es echa,
aca va un ejemplo de lo que veo


=> Booting WEBrick
=> Rails 3.0.1 application starting in development on http://0.0.0.0:3000
=> Call with -d to detach
=> Ctrl-C to shutdown server
[2011-01-18 16:22:28] INFO  WEBrick 1.3.1
[2011-01-18 16:22:28] INFO  ruby 1.9.2 (2010-08-18) [i686-linux]
[2011-01-18 16:22:28] INFO  WEBrick::HTTPServer#start: pid=8766 port=3000
Got notification: #<ActiveSupport::Notifications::Event:0xc1121d0
@name="start_processing.action_controller",
@payload={:controller=>"HomeController", :action=>"index",
:params=>{"controller"=>"home", "action"=>"index"}, :formats=>[:html],
:method=>"GET", :path=>"/"}, @time=2011-01-18 16:23:05 -0300,
@transaction_id="1f5120286cd9604a2907", @end=2011-01-18 16:23:05 -0300,
@duration=0.005308>
Got notification: #<ActiveSupport::Notifications::Event:0xc0505e4
@name="sql.active_record", @payload={:sql=>"SHOW TABLES", :name=>"SQL",
:connection_id=>100167550}, @time=2011-01-18 16:23:05 -0300,
@transaction_id="1f5120286cd9604a2907", @end=2011-01-18 16:23:05 -0300,
@duration=0.570813>
*... (un monton algo similar aca)...*
Got notification: #<ActiveSupport::Notifications::Event:0xb3891d0
@name="process_action.action_controller",
@payload={:controller=>"HomeController", :action=>"index",
:params=>{"controller"=>"home", "action"=>"index"}, :formats=>[:html],
:method=>"GET", :path=>"/", :status=>200, :view_runtime=>141.89233525012207,
:db_runtime=>0.955918}, @time=2011-01-18 16:23:05 -0300,
@transaction_id="1f5120286cd9604a2907", @end=2011-01-18 16:23:05 -0300,
@duration=143.225468>


Started GET "/" for 127.0.0.1 at 2011-01-18 16:23:05 -0300
  Processing by HomeController#index as HTML
  SQL (0.6ms)  SHOW TABLES
  User Load (0.2ms)  SELECT `users`.* FROM `users` WHERE (`users`.`id` = 12)
LIMIT 1
  Account Load (0.2ms)  SELECT `accounts`.* FROM `accounts` WHERE
(`accounts`.user_id = 12) LIMIT 1
Rendered layouts/_header.html.erb (41.4ms)
Rendered layouts/_footer.html.haml (3.6ms)
Rendered home/index.html.haml within layouts/application (139.4ms)
Completed 200 OK in 143ms (Views: 141.9ms | ActiveRecord: 1.0ms)



esto es bastante molesto dado que también lo veo cuando uso la consola, por
ejemplo,

$> rails c
ruby-1.9.2-p0 > u = User.find_by_email('xxx@hotmail.com')
Got notification: #<ActiveSupport::Notifications::Event:0xab3b654
@name="sql.active_record", @payload={:sql=>"SHOW TABLES", :name=>"SQL",
:connection_id=>89880460}, @time=2011-01-18 16:17:40 -0300,
@transaction_id="623814d5c14f9eef2a69", @end=2011-01-18 16:17:40 -0300,
@duration=0.649036>
Got notification: #<ActiveSupport::Notifications::Event:0xa1332ec
@name="sql.active_record", @payload={:sql=>"SELECT     `users`.* FROM
`users`  WHERE     (`users`.`email` = 'xxx@hotmail.com') LIMIT 1",
:name=>"User Load", :connection_id=>89880460}, @time=2011-01-18 16:17:40
-0300, @transaction_id="623814d5c14f9eef2a69", @end=2011-01-18 16:17:40
-0300, @duration=0.363105>
 => #<User id: 12, email: "xxx@hotmail.com", encrypted_password: "",
password_salt: "", confirmation_token: nil, confirmed_at: "2010-12-16
19:46:38", confirmation_sent_at: "2010-12-16 19:46:34",
reset_password_token: nil, remember_token: nil, remember_created_at: nil,
sign_in_count: 26, current_sign_in_at: "2011-01-18 11:45:45",
last_sign_in_at: "2011-01-13 20:48:24", current_sign_in_ip: "127.0.0.1",
last_sign_in_ip: "127.0.0.1", created_at: "2010-12-16 19:46:34", updated_at:
"2011-01-18 11:45:45", roles_mask: 1>
ruby-1.9.2-p0 > u.timeline
Got notification: #<ActiveSupport::Notifications::Event:0x973a628
@name="sql.active_record", @payload={:sql=>"SELECT     `timelines`.* FROM
    `timelines`  WHERE     (`timelines`.user_id = 12) LIMIT 1",
:name=>"Timeline Load", :connection_id=>89880460}, @time=2011-01-18 16:17:52
-0300, @transaction_id="623814d5c14f9eef2a69", @end=2011-01-18 16:17:52
-0300, @duration=0.145269>
 => #<Timeline id: 12, user_id: 12, created_at: "2010-12-16 19:46:38",
updated_at: "2010-12-16 19:46:38">
ruby-1.9.2-p0 > u.timeline.stages
Got notification: #<ActiveSupport::Notifications::Event:0x90fafb0
@name="sql.active_record", @payload={:sql=>"SELECT     `stages`.* FROM
`stages`  WHERE     (`stages`.timeline_id = 12) ORDER BY  from_date",
:name=>"Stage Load", :connection_id=>89880460}, @time=2011-01-18 16:17:55
-0300, @transaction_id="623814d5c14f9eef2a69", @end=2011-01-18 16:17:55
-0300, @duration=0.168038>
 => [#<Stage id: 7, from_date: "1930-01-01", to_date: "1930-01-21", name:
"Años 30", timeline_id: 12, created_at: "2010-12-16 19:47:13", updated_at:
"2011-01-13 21:08:52">, #<Stage id: 8, from_date: "1990-01-01", to_date:
"1990-07-20", name: "Decada del 90", timeline_id: 12, created_at:
"2010-12-16 19:47:46", updated_at: "2011-01-13 21:09:16">, #<Stage id: 9,
from_date: "2005-12-31", to_date: "2010-12-31", name: "Universidad",
timeline_id: 12, created_at: "2010-12-16 20:27:40", updated_at: "2010-12-16
20:27:40">]
ruby-1.9.2-p0 > u.timeline.stages.size
 => 3


Probé bajar el nivel de logging editando el archivo
config/environments/development.rb

  config.active_support.log_activity = false
  config.active_support.log_level = :info
  config.log_level = :info
  ActiveRecord::LogSubscriber.flush_all!


pero nada de esto funciona, también intenté usar el
método unsubscribe(*args) de ActiveSupport::Notifications que encontré en la
API de Rails pero tampoco anduvo. Bueno, espero que alguien pueda ayudarme
con esto, seguramente es algo de configuración que toqué :s. Ah también
busqué en todas las gemas que estoy usando y no encontré nada.

Saludos,
Franco.

Re: [rubysur] log en rails 3

From:
Luis Lavena
Date:
2011-01-18 @ 19:34
2011/1/18 Franco Brusatti <fbrusatti@gmail.com>:
> Hola gente,
>   tengo un inconveniente con los logs en una app en rails 3, el tema es que
> veo un monton de notificaciones en el log (en modo desarrollo y producción
> también), chequeando el archivo log/development.rb me doy cuenta que no se
> estan grabando ahi pero se ven en la pantalla cuando una consulta es echa,
> aca va un ejemplo de lo que veo
>

Se ve en la consola por que no estas "detachando" el proceso. ejecuta
"rails server -d" para que el logging se haga en log/development.log

En lo que respecta a produccion, como estas corriendo la aplicacion?
tambien con rails server? especificaste el environment?

> esto es bastante molesto dado que también lo veo cuando uso la consola, por
> ejemplo,
>

Si ve eso en tu consola, fijate que no estes haciendo un Rails.logger
= Logger.new(STDOUT) en algun lado, generalmente en ~/.irbrc

Fijate lo que te menciono arriba y decinos.

-- 
Luis Lavena
AREA 17
-
Perfection in design is achieved not when there is nothing more to add,
but rather when there is nothing more to take away.
Antoine de Saint-Exupéry

Re: [rubysur] log en rails 3

From:
Franco Brusatti
Date:
2011-01-18 @ 20:00
2011/1/18 Luis Lavena <luislavena@gmail.com>

> 2011/1/18 Franco Brusatti <fbrusatti@gmail.com>:
> > Hola gente,
> >   tengo un inconveniente con los logs en una app en rails 3, el tema es
> que
> > veo un monton de notificaciones en el log (en modo desarrollo y
> producción
> > también), chequeando el archivo log/development.rb me doy cuenta que no
> se
> > estan grabando ahi pero se ven en la pantalla cuando una consulta es
> echa,
> > aca va un ejemplo de lo que veo
> >
>
> Se ve en la consola por que no estas "detachando" el proceso. ejecuta
> "rails server -d" para que el logging se haga en log/development.log
>

buenisimo esto Luis, va mejorando gracias, ahora arranqué el server con
"rails s -d" y luego ligué el archivo de log con "tail -f
log/development.rb"


> En lo que respecta a produccion, como estas corriendo la aplicacion?
> tambien con rails server? especificaste el environment?
>
En producción la verdad no me interesa mucho dado que inpecciono muy pocas
veces el log en el servidor de producción.


> > esto es bastante molesto dado que también lo veo cuando uso la consola,
> por
> > ejemplo,
> >
>
> Si ve eso en tu consola, fijate que no estes haciendo un Rails.logger
> = Logger.new(STDOUT) en algun lado, generalmente en ~/.irbrc
>

lo de la consola todavía no lo soluciono, lo raro de esto es que lo empezó a
hacerlo un día x, es decir, es algo que hice yo en algún momento. Intenté
desuscribir a ActiveRecord de la siguiente forma

ruby-1.9.2-p0 > subscribers = ActiveRecord::LogSubscriber.log_subscribers
 => [#<ActionView::LogSubscriber:0x9b2b534>,
#<ActionController::LogSubscriber:0x9a77c50>,
#<ActiveRecord::LogSubscriber:0x9ac11fc @odd_or_even=false>,
#<ActionMailer::LogSubscriber:0x9cc28fc>]

ruby-1.9.2-p0 > ar_subscriber  = subscribers[2]
 => #<ActiveRecord::LogSubscriber:0x9ac11fc @odd_or_even=false>

ruby-1.9.2-p0 > ActiveSupport::Notifications.unsubscribe(ar_subscriber)
 => {}

ruby-1.9.2-p0 > u = User.find_by_email('xxx@gmail.com')
Got notification: #<ActiveSupport::Notifications::Event:0x9c49628
@name="sql.active_record", @payload={:sql=>"SELECT     `users`.* FROM
`users`  WHERE     (`users`.`email` = 'xxx@gmail.com') LIMIT 1",
:name=>"User Load", :connection_id=>87826520}, @time=2011-01-18 16:56:03
-0300, @transaction_id="0120551cc1f51324775a", @end=2011-01-18 16:56:03
-0300, @duration=0.6883549999999999>
 => nil

pero evidentemente hice cualquiera porque como se puede ver en rojo sigo
viendo esos eventos en la consola

Saludos y gracias,
Franco.

Re: [rubysur] log en rails 3

From:
Luis Lavena
Date:
2011-01-18 @ 20:06
2011/1/18 Franco Brusatti <fbrusatti@gmail.com>:
>
> buenisimo esto Luis, va mejorando gracias, ahora arranqué el server con
> "rails s -d" y luego ligué el archivo de log con "tail -f
> log/development.rb"
>

Este, no, el log es log/development.log, no .rb

>>
>> > esto es bastante molesto dado que también lo veo cuando uso la consola,
>> > por
>> > ejemplo,
>> >
>>
>> Si ve eso en tu consola, fijate que no estes haciendo un Rails.logger
>> = Logger.new(STDOUT) en algun lado, generalmente en ~/.irbrc
>
> lo de la consola todavía no lo soluciono, lo raro de esto es que lo empezó a
> hacerlo un día x, es decir, es algo que hice yo en algún momento. Intenté
> desuscribir a ActiveRecord de la siguiente forma
>
> ruby-1.9.2-p0 > subscribers = ActiveRecord::LogSubscriber.log_subscribers
>  => [#<ActionView::LogSubscriber:0x9b2b534>,
> [...]
> pero evidentemente hice cualquiera porque como se puede ver en rojo sigo
> viendo esos eventos en la consola

El nivel de logging no tiene nada que ver con el la subscripcion a
eventos de ActiveRecord.

Si no esta en irbrc como te mencione, entonces esta en el codigo de tu
aplicacion.

Git bisect es lo unico que te puedo decir :)
-- 
Luis Lavena
AREA 17
-
Perfection in design is achieved not when there is nothing more to add,
but rather when there is nothing more to take away.
Antoine de Saint-Exupéry

Re: [rubysur] log en rails 3

From:
Franco Brusatti
Date:
2011-01-18 @ 20:13
2011/1/18 Luis Lavena <luislavena@gmail.com>

> 2011/1/18 Franco Brusatti <fbrusatti@gmail.com>:
> >
> > buenisimo esto Luis, va mejorando gracias, ahora arranqué el server con
> > "rails s -d" y luego ligué el archivo de log con "tail -f
> > log/development.rb"
> >
>
> Este, no, el log es log/development.log, no .rb
>
si si, error mio por tipear :P


>
> >>
> >> > esto es bastante molesto dado que también lo veo cuando uso la
> consola,
> >> > por
> >> > ejemplo,
> >> >
> >>
> >> Si ve eso en tu consola, fijate que no estes haciendo un Rails.logger
> >> = Logger.new(STDOUT) en algun lado, generalmente en ~/.irbrc
> >
> > lo de la consola todavía no lo soluciono, lo raro de esto es que lo
> empezó a
> > hacerlo un día x, es decir, es algo que hice yo en algún momento. Intenté
> > desuscribir a ActiveRecord de la siguiente forma
> >
> > ruby-1.9.2-p0 > subscribers = ActiveRecord::LogSubscriber.log_subscribers
> >  => [#<ActionView::LogSubscriber:0x9b2b534>,
> > [...]
> > pero evidentemente hice cualquiera porque como se puede ver en rojo sigo
> > viendo esos eventos en la consola
>
> El nivel de logging no tiene nada que ver con el la subscripcion a
> eventos de ActiveRecord.
>
> Si no esta en irbrc como te mencione, entonces esta en el codigo de tu
> aplicacion.
>
> Git bisect es lo unico que te puedo decir :)
>
jeje, si si, voy a tener que hacer algo de esto, gracias por leer el post.

Saludos,
Franco.