How to capture Oracle's dbms_output in your Rails log file

August 19, 2009

I have been writing a rails application on top of a large existing Oracle database where each table has 5+ triggers that each call several stored procedures and each of those PL/SQL stored procedures is hundreds of lines long. Often a simple update statement fails with an ORA-xxxx exception coming from deep in the PL/SQL code and it can be tough to figure out what's gone wrong.

The usual way Oracle database folks figure out what's going on is to put print statements in their code. In oracle this looks like

  dbms_output.put_line('hi i hit this line of pl/sql');

When you're using an Oracle editor like TOAD or SQLDeveloper you have to turn output on and then will see anything that's printed.

  set serveroutput on;

This is great if you divide the application between Rails
and Database developers and assume each group can work independently to write perfect code but what about the real world!
Today I want to show you how I monkey patched the Oracle Enhanced Adapter to stick the dbms_output into
the rails log file.

Let's start with an simple example of a simple PL/SQL function that tells you if a string is more than 5 characters long (with some simple debugging print statements).

  CREATE OR REPLACE FUNCTION
  MORE_THAN_FIVE_CHARACTERS_LONG (some_text VARCHAR2) RETURN INTEGER
  AS
  longer_than_five INTEGER;
  BEGIN
    dbms_output.put_line('before the if -' || some_text || '-');
    IF length(some_text) > 5 THEN
      dbms_output.put_line('it is longer than 5');
      longer_than_five := 1;
    ELSE
      dbms_output.put_line('it is 5 or shorter');
      longer_than_five := 0;
    END IF;
    dbms_output.put_line('about to return: ' || longer_than_five);
    RETURN longer_than_five;
  END;

Now we can run the following in TOAD

  set serveroutput on;
  select MORE_THAN_FIVE_CHARACTERS_LONG('a long string') from dual;
  select MORE_THAN_FIVE_CHARACTERS_LONG('short') from dual;

And we get this output

  MORE_THAN_FIVE_CHARACTERS_LONG('ALONGSTRING') 
  --------------------------------------------- 
  1                                             

  1 rows selected

  before the if -a long string-
  it is longer than 5
  about to return: 1

  MORE_THAN_FIVE_CHARACTERS_LONG('SHORT') 
  --------------------------------------- 
  0                                       

  1 rows selected

  before the if -short-
  it is 5 or shorter
  about to return: 0

To get the same in our Rails app we just need to monkey patch the OracleEnhancedAdapter by copying what's below into your project as config/initializers/oracle_enhanced_adapter.rb

  module ActiveRecord
    module ConnectionAdapters
      class OracleEnhancedAdapter < AbstractAdapter
        DBMS_OUTPUT_BUFFER_SIZE = 10000  #can be 1-1000000
        DBMS_LINE_MAX_SIZE      = 1000  
        def enable_dbms_output
          @enable_dbms_output = true
          execute "BEGIN dbms_output.enable(#{DBMS_OUTPUT_BUFFER_SIZE}); END;"
        end
        def disable_dbms_output
          @enable_dbms_output = false
          execute "BEGIN dbms_output.disable(); END;"
        end
        def dbms_output_enabled?
          @enable_dbms_output
        end

        protected
          def log(sql, name)
            super(sql, name)
          ensure
            log_all_dbms_output if dbms_output_enabled?
          end

        private  
          def log_next_line_of_dbms_output
            dbms_output_text, status = @connection.exec "BEGIN dbms_output.get_line(:return, :status); END;", ' '*DBMS_LINE_MAX_SIZE, 1
            got_text = (status == 0)
            @logger.debug "DBMS_OUTPUT: #{dbms_output_text}" if got_text
            got_text
          end
        
          def log_all_dbms_output
            while log_next_line_of_dbms_output do
            end
          end
      end
    end
  end

To use it let's show a quick script/console session

  >> ActiveRecord::Base.connection.enable_dbms_output
  => []
  >> ActiveRecord::Base.connection.select_all("select MORE_THAN_FIVE_CHARACTERS_LONG('a long string') from dual")
  => [{"more_than_five_characters_long('alongstring')"=>1}]

And what's in log/development.log


    SQL (27.0ms)   BEGIN dbms_output.enable(10000); END;
    SQL (25.9ms)   select MORE_THAN_FIVE_CHARACTERS_LONG('a long string') from dual
  DBMS_OUTPUT: before the if -a long string-
  DBMS_OUTPUT: it is longer than 5
  DBMS_OUTPUT: about to return: 1

This is admittedly a very simple example but I have used this in a real application where I am updating several related ActiveRecord objects and seeing the DBMS_OUTPUT inline with the various SQL update statements has been extremely useful in tracking down a real bug in the PL/SQL procedure that has been in our system for over a year!

I've submitted this as a patch to the Oracle Enhanced Adapter so perhaps it will be included at some point so you wont have to do the monkey patching yourself. I was somewhat surprised not to find anything similar out there so if you know of something please leave a comment.

AlexRothenberg

How to capture Oracle's dbms_output in your Rails log file