This project is archived and is in readonly mode.

#3388 ✓resolved
Sam Ruby

ActiveRecord splits log records across multiple lines

Reported by Sam Ruby | October 18th, 2009 @ 02:14 AM | in 3.0.2

Given the following statement:

order = Order.find(:first)

Rails 2.3.4 produces the following log entry:

  Order Load (1.5ms)   SELECT * FROM "orders" LIMIT 1

Now that ARel has landed, Rails 3.0pre produces the following log entries:

  Order Load (1.1ms)   SELECT *
FROM "orders"
LIMIT 1

This clearly isn't a bug, but arguably is a fit and finish item, as putting log entries on one line would make it easier to scan. At a minimum, subsequent lines should be indented or otherwise easily identified as a continuation.

Comments and changes to this ticket

  • Jeremy Kemper

    Jeremy Kemper November 24th, 2009 @ 05:39 PM

    • Assigned user changed from “Yehuda Katz (wycats)” to “Jeremy Kemper”
    • State changed from “new” to “open”
    • Milestone cleared.

    Yup - one line is preferable.

  • Sam Ruby

    Sam Ruby December 9th, 2009 @ 03:22 PM

    It has since gotten even less usable, as ANSI screen control characters are now included in the log itself.

      *[4;36;1msql (0.0ms)*[0m   *[0;1mSELECT *
    FROM "products"
    ORDER BY title*[0m
    

    A few well placed gsubs could clean this right up.

    line.gsub! "\n", ' '
    line.gsub! /\x1b\[\d(;\d+)*m/, ''
    
  • Ben Marini

    Ben Marini January 17th, 2010 @ 09:35 PM

    You can solve the ANSI control characters issue with config.colorize_logging = false.

    As for the multiline SQL, I would almost say it's an easy fix in ActiveRecord::Railties::Subscriber:

    - sql  = event.payload[:sql].squeeze(' ')
    + sql  = event.payload[:sql].gsub(/\s+/, ' ').strip
    

    The only problem with this (and with the current use of #squeeze) is that there is the possibility you'll inadvertently change the SQL statement itself! For instance, queries with intentional extra spaces in a condition:

    "SELECT * FROM table_a WHERE col1 LIKE 'something  something else'" # Note the double space in LIKE clause
    

    This is probably a rare case, but I think it's pretty important for the logger to log the same SQL that was presented to the connection adapter. Maybe the white space can be trimmed ahead of time, before it reaches the logger?

  • Daniel Guettler

    Daniel Guettler January 18th, 2010 @ 04:28 AM

    I cannot reproduce this; logs look fine to me using the latest version of rails. I tried both sqlite and mysql.

    Migrating to CreateOrders (20100118042221)
      SQL (0.2ms)  select sqlite_version(*)
      SQL (0.6ms)  CREATE TABLE "orders" ("id" INTEGER PRIMARY KEY AUTOINCREMENT NOT NULL, "name" varchar(255), "created_at" datetime, "updated_at" datetime) 
      Order Load (0.3ms)  SELECT "orders"."id", "orders"."name", "orders"."created_at", "orders"."updated_at" FROM "orders" LIMIT 1
    
    Migrating to CreateOrders (20100118042221)
      SQL (95.3ms)  CREATE TABLE `schema_migrations` (`version` varchar(255) NOT NULL) ENGINE=InnoDB
      SQL (47.8ms)  CREATE UNIQUE INDEX `unique_schema_migrations` ON `schema_migrations` (`version`)
      SQL (0.3ms)  SET SQL_AUTO_IS_NULL=0
      orders Columns (74.2ms)  SHOW FIELDS FROM `orders`
      Order Load (0.3ms)  SELECT `orders`.`id`, `orders`.`name`, `orders`.`created_at`, `orders`.`updated_at` FROM `orders` LIMIT 1
    

    Am I missing something here?

  • Sam Ruby

    Sam Ruby February 3rd, 2010 @ 12:57 PM

    • State changed from “open” to “resolved”
  • Jeremy Kemper

    Jeremy Kemper October 15th, 2010 @ 11:01 PM

    • Milestone set to 3.0.2
    • Importance changed from “” to “Low”
  • Jeff Kreeftmeijer

Create your profile

Help contribute to this project by taking a few moments to create your personal profile. Create your profile »

<h2 style="font-size: 14px">Tickets have moved to Github</h2>

The new ticket tracker is available at <a href="https://github.com/rails/rails/issues">https://github.com/rails/rails/issues</a>

Pages