random OCIErrors

19 views
Skip to first unread message

volkr...@gmail.com

unread,
Apr 12, 2018, 11:43:35 AM4/12/18
to Oracle enhanced adapter for ActiveRecord
Hi,
i am currently investigating a problem and hope someone has seen something similar. The application randomly throws OCIErrors. In the logfile 1 below you can see the exact same SQL Query two times, but the error is only thrown for the first one. The second query goes through without problem. This behaviour occurs after the application has run for some days, but very randomly. Sometimes it happens every request, sometimes only every fifth request. Another exampler is in logfile 2. A restart of the app always solves the problem, after that every request works without error. I couldn't emulate the problem in my dev environment and have no clue what's the source.

Thanks
Volker

System:
RUBY VERSION: 2.3.3
rails (5.1.5)
activerecord-oracle_enhanced-adapter (1.8.2)
ruby-oci8 (2.2.5.1)
puma (3.11.2) (4 workers in production)


Logfile 1:


I, [2018-04-04T12:54:33.132730 #28388]  INFO -- : [78ee6c99-8e9a-408a-ac0f-401bbb3c6c5a] Started GET "/kvts-api/termins/search/?fachgruppe=1,520,10,547,552,85,86,89,328,326,82,548,545,551,84,81,327,83,87,321,80,88,521,522,523,541,540,524,525,526,527,528&stadtteile=&zeitraum=10&status=frei" for 127.0.0.1 at 2018-04-04 12:54:33 +0000
I, [2018-04-04T12:54:33.133625 #28388]  INFO -- : [78ee6c99-8e9a-408a-ac0f-401bbb3c6c5a] Processing by TerminsController#search as HTML
I, [2018-04-04T12:54:33.133687 #28388]  INFO -- : [78ee6c99-8e9a-408a-ac0f-401bbb3c6c5a]   Parameters: {"fachgruppe"=>"1,520,10,547,552,85,86,89,328,326,82,548,545,551,84,81,327,83,87,321,80,88,521,522,523,541,540,524,525,526,527,528", "stadtteile"=>"", "zeitraum"=>"10", "status"=>"frei"}
D, [2018-04-04T12:54:33.137832 #28388] DEBUG -- : [78ee6c99-8e9a-408a-ac0f-401bbb3c6c5a]   ^[[1m^[[36mUsershell Load (1.2ms)^[[0m  ^[[1m^[[34mSELECT  "USERSHELLS".* FROM "USERSHELLS" WHERE "USERSHELLS"."ID" = :a1 AND ROWNUM <= :a2 ^[[0m  [["id", 10030], ["LIMIT", 1]]
D, [2018-04-04T12:54:33.144149 #28388] DEBUG -- : [78ee6c99-8e9a-408a-ac0f-401bbb3c6c5a]   ^[[1m^[[36mTermin Load (2.0ms)^[[0m  ^[[1m^[[34mSELECT "TERMINS".* FROM "TERMINS" WHERE (zeitpunkt >= '2018-04-04') AND (behandlerfachgruppe in ('1','520','10','547','552','85','86','89','328','326','82','548','545','551','84','81','327','83','87','321','80','88','521','522','523','541','540','524','525','526','527','528')) AND (zeitpunkt <= '2018-04-14') AND (status in ('frei'))^[[0m
I, [2018-04-04T12:54:33.144406 #28388]  INFO -- : [78ee6c99-8e9a-408a-ac0f-401bbb3c6c5a] Completed 500 Internal Server Error in 11ms (ActiveRecord: 3.2ms)

F, [2018-04-04T12:54:33.145036 #28388] FATAL -- : [78ee6c99-8e9a-408a-ac0f-401bbb3c6c5a]
F, [2018-04-04T12:54:33.145077 #28388] FATAL -- : [78ee6c99-8e9a-408a-ac0f-401bbb3c6c5a] ActiveRecord::StatementInvalid (OCIError: ORA-01843: Kein gültiger Monat: SELECT "TERMINS".* FROM "TERMINS" WHERE (zeitpunkt >= '2018-04-04') AND (behandlerfachgruppe in ('1','520','10','547','552','85','86','89','328','326','82','548','545','551','84','81','327','83','87','321','80','88','521','522','523','541','540','524','525','526','527','528')) AND (zeitpunkt <= '2018-04-14') AND (status in ('frei'))):
F, [2018-04-04T12:54:33.145102 #28388] FATAL -- : [78ee6c99-8e9a-408a-ac0f-401bbb3c6c5a]
F, [2018-04-04T12:54:33.145124 #28388] FATAL -- : [78ee6c99-8e9a-408a-ac0f-401bbb3c6c5a] app/controllers/termins_controller.rb:16:in `sort_by'
[78ee6c99-8e9a-408a-ac0f-401bbb3c6c5a] app/controllers/termins_controller.rb:16:in `search'
I, [2018-04-04T12:54:40.184961 #28359]  INFO -- : [39aa0744-ba71-4c08-a48b-e7551596fcd2] Started GET "/kvts-api/termins/search/?fachgruppe=1,520,10,547,552,85,86,89,328,326,82,548,545,551,84,81,327,83,87,321,80,88,521,522,523,541,540,524,525,526,527,528&stadtteile=&zeitraum=10&status=frei" for 127.0.0.1 at 2018-04-04 12:54:40 +0000
I, [2018-04-04T12:54:40.186147 #28359]  INFO -- : [39aa0744-ba71-4c08-a48b-e7551596fcd2] Processing by TerminsController#search as HTML
I, [2018-04-04T12:54:40.186220 #28359]  INFO -- : [39aa0744-ba71-4c08-a48b-e7551596fcd2]   Parameters: {"fachgruppe"=>"1,520,10,547,552,85,86,89,328,326,82,548,545,551,84,81,327,83,87,321,80,88,521,522,523,541,540,524,525,526,527,528", "stadtteile"=>"", "zeitraum"=>"10", "status"=>"frei"}
D, [2018-04-04T12:54:40.191164 #28359] DEBUG -- : [39aa0744-ba71-4c08-a48b-e7551596fcd2]   ^[[1m^[[36mUsershell Load (2.2ms)^[[0m  ^[[1m^[[34mSELECT  "USERSHELLS".* FROM "USERSHELLS" WHERE "USERSHELLS"."ID" = :a1 AND ROWNUM <= :a2 ^[[0m  [["id", 10030], ["LIMIT", 1]]
D, [2018-04-04T12:54:40.207956 #28359] DEBUG -- : [39aa0744-ba71-4c08-a48b-e7551596fcd2]   ^[[1m^[[36mTermin Load (11.6ms)^[[0m  ^[[1m^[[34mSELECT "TERMINS".* FROM "TERMINS" WHERE (zeitpunkt >= '2018-04-04') AND (behandlerfachgruppe in ('1','520','10','547','552','85','86','89','328','326','82','548','545','551','84','81','327','83','87','321','80','88','521','522','523','541','540','524','525','526','527','528')) AND (zeitpunkt <= '2018-04-14') AND (status in ('frei'))^[[0m same params like before, but no error
D, [2018-04-04T12:54:40.291113 #28359] DEBUG -- : [39aa0744-ba71-4c08-a48b-e7551596fcd2]   ^[[1m^[[36mBststamm Load (77.3ms)^[[0m  ^[[1m^[[34mSELECT  "BSTSTAMMS".* FROM "BSTSTAMMS" WHERE "BSTSTAMMS"."BT_BSNR" = :a1 AND ROWNUM <= :a2 ^[[0m  [["bt_bsnr", 21019598], ["LIMIT", 1]]
D, [2018-04-04T12:54:40.291699 #28359] DEBUG -- : [39aa0744-ba71-4c08-a48b-e7551596fcd2]   ^[[1m^[[36mCACHE Bststamm Load (0.0ms)^[[0m  ^[[1m^[[34mSELECT  "BSTSTAMMS".* FROM "BSTSTAMMS" WHERE "BSTSTAMMS"."BT_BSNR" = :a1 AND ROWNUM <= :a2 ^[[0m  [["bt_bsnr", 21019598], ["LIMIT", 1]]
D, [2018-04-04T12:54:40.293015 #28359] DEBUG -- : [39aa0744-ba71-4c08-a48b-e7551596fcd2]   ^[[1m^[[36mBstaenderungen Load (0.9ms)^[[0m  ^[[1m^[[34mSELECT  "BSTAENDERUNGENS".* FROM "BSTAENDERUNGENS" WHERE "BSTAENDERUNGENS"."BSNR" = :a1 AND ROWNUM <= :a2 ^[[0m  [["bsnr", "21019598"], ["LIMIT", 1]]



Logfile 2:

Started POST "/usershell_token" for 127.0.0.1 at 2017-12-14 15:35:44 +0100
Processing by UsershellTokenController#create as HTML
  Parameters: {"auth"=>{"loginParam"=>"w%2F6veTVLudU%3D%2CwI%2FoEt9cARUR6pCFhk%2BvTDKkT%2FggF8QZrI1IvhP3qLf%2BRSZxl6K2%2BT4MKkrz%2Bfq5rb3vvezFVuZ1%0AXSnwH8Q2DHGPX0C5Lq4m"}, "usershell_token"=>{"auth"=>{"loginParam"=>"w%2F6veTVLudU%3D%2CwI%2FoEt9cARUR6pCFhk%2BvTDKkT%2FggF8QZrI1IvhP3qLf%2BRSZxl6K2%2BT4MKkrz%2Bfq5rb3vvezFVuZ1%0AXSnwH8Q2DHGPX0C5Lq4m"}}}
*** TIMESTAMP TO OLD *** 1513247219915
  [1m [36mUsershell Load (2.0ms) [0m  [1m [34mSELECT  "USERSHELLS".* FROM "USERSHELLS" WHERE "USERSHELLS"."LANR" = :a1 AND ROWNUM <= :a2 [0m  [["lanr", "7323331"], ["LIMIT", 1]]
  [1m [36mBststamm Load (325.0ms) [0m  [1m [34mSELECT  "BSTSTAMMS".* FROM "BSTSTAMMS" WHERE "BSTSTAMMS"."AR_LANR" = :a1 AND ROWNUM <= :a2 [0m  [["ar_lanr", 7323331], ["LIMIT", 1]]
Completed 500 Internal Server Error in 333ms (ActiveRecord: 327.0ms)


 
ActiveRecord::StatementInvalid (OCIError: ORA-00932: Inkonsistente Datentypen: NUMBER erwartet, DATE erhalten: SELECT  "BSTSTAMMS".* FROM "BSTSTAMMS" WHERE "BSTSTAMMS"."AR_LANR" = :a1 AND ROWNUM <= :a2 ):
 
app/models/usershell.rb:33:in `from_token_request'

Started POST "/usershell_token" for 127.0.0.1 at 2017-12-14 15:37:06 +0100
Processing by UsershellTokenController#create as HTML
  Parameters: {"auth"=>{"loginParam"=>"w%2F6veTVLudU%3D%2CwI%2FoEt9cARUR6pCFhk%2BvTDKkT%2FggF8QZrI1IvhP3qLf%2BRSZxl6K2%2BT4MKkrz%2Bfq5rb3vvezFVuZ1%0AXSnwH8Q2DHGPX0C5Lq4m"}, "usershell_token"=>{"auth"=>{"loginParam"=>"w%2F6veTVLudU%3D%2CwI%2FoEt9cARUR6pCFhk%2BvTDKkT%2FggF8QZrI1IvhP3qLf%2BRSZxl6K2%2BT4MKkrz%2Bfq5rb3vvezFVuZ1%0AXSnwH8Q2DHGPX0C5Lq4m"}}}
*** TIMESTAMP TO OLD *** 1513247219915
  [1m [35m (14.0ms) [0m  [1m [34mSELECT cols.column_name AS name, cols.data_type AS sql_type, cols.data_default, cols.nullable, cols.virtual_column, cols.hidden_column, cols.data_type_owner AS sql_type_owner, DECODE(cols.data_type, 'NUMBER', data_precision, 'FLOAT', data_precision, 'VARCHAR2', DECODE(char_used, 'C', char_length, data_length), 'RAW', DECODE(char_used, 'C', char_length, data_length), 'CHAR', DECODE(char_used, 'C', char_length, data_length), NULL) AS limit, DECODE(data_type, 'NUMBER', data_scale, NULL) AS scale, comments.comments as column_comment FROM all_tab_cols cols, all_col_comments comments WHERE cols.owner = 'COMET' AND cols.table_name = 'USERSHELLS' AND cols.hidden_column = 'NO' AND cols.owner = comments.owner AND cols.table_name = comments.table_name AND cols.column_name = comments.column_name ORDER BY cols.column_id [0m
  [1m [36mUsershell Load (2.0ms) [0m  [1m [34mSELECT  "USERSHELLS".* FROM "USERSHELLS" WHERE "USERSHELLS"."LANR" = :a1 AND ROWNUM <= :a2 [0m  [["lanr", "7323331"], ["LIMIT", 1]]
  [1m [35m (26.0ms) [0m  [1m [34mSELECT cols.column_name AS name, cols.data_type AS sql_type, cols.data_default, cols.nullable, cols.virtual_column, cols.hidden_column, cols.data_type_owner AS sql_type_owner, DECODE(cols.data_type, 'NUMBER', data_precision, 'FLOAT', data_precision, 'VARCHAR2', DECODE(char_used, 'C', char_length, data_length), 'RAW', DECODE(char_used, 'C', char_length, data_length), 'CHAR', DECODE(char_used, 'C', char_length, data_length), NULL) AS limit, DECODE(data_type, 'NUMBER', data_scale, NULL) AS scale, comments.comments as column_comment FROM all_tab_cols cols, all_col_comments comments WHERE cols.owner = 'COMET' AND cols.table_name = 'BSTSTAMMS' AND cols.hidden_column = 'NO' AND cols.owner = comments.owner AND cols.table_name = comments.table_name AND cols.column_name = comments.column_name ORDER BY cols.column_id [0m
  [1m [36mBststamm Load (195.0ms) [0m  [1m [34mSELECT  "BSTSTAMMS".* FROM "BSTSTAMMS" WHERE "BSTSTAMMS"."AR_LANR" = :a1 AND ROWNUM <= :a2 [0m  [["ar_lanr", 7323331], ["LIMIT", 1]]  same params like before, no error
  [1m [35m (6.0ms) [0m  [1m [34mSELECT LOWER(view_name) FROM all_views WHERE owner = SYS_CONTEXT('userenv', 'current_schema') [0m
  [1m [36mSequence (3.0ms) [0m  [1m [34mselect us.sequence_name from all_sequences us where us.sequence_owner = 'COMET' and us.sequence_name = upper('BSTSTAMMS_seq') [0m
  [1m [36mPrimary Key (6.0ms) [0m  [1m [34mSELECT cc.column_name FROM all_constraints c, all_cons_columns cc WHERE c.owner = 'COMET' AND c.table_name = 'BSTSTAMMS' AND c.constraint_type = 'P' AND cc.owner = c.owner AND cc.constraint_name = c.constraint_name [0m
  [1m [36mBststamm Load (455.0ms) [0m  [1m [34mSELECT "BSTSTAMMS".* FROM "BSTSTAMMS" WHERE "BSTSTAMMS"."AR_LANR" = :a1 [0m  [["ar_lanr", 7323331]]
  [1m [35m (13.0ms) [0m  [1m [34mSELECT cols.column_name AS name, cols.data_type AS sql_type, cols.data_default, cols.nullable, cols.virtual_column, cols.hidden_column, cols.data_type_owner AS sql_type_owner, DECODE(cols.data_type, 'NUMBER', data_precision, 'FLOAT', data_precision, 'VARCHAR2', DECODE(char_used, 'C', char_length, data_length), 'RAW', DECODE(char_used, 'C', char_length, data_length), 'CHAR', DECODE(char_used, 'C', char_length, data_length), NULL) AS limit, DECODE(data_type, 'NUMBER', data_scale, NULL) AS scale, comments.comments as column_comment FROM all_tab_cols cols, all_col_comments comments WHERE cols.owner = 'COMET' AND cols.table_name = 'BSTAENDERUNGENS' AND cols.hidden_column = 'NO' AND cols.owner = comments.owner AND cols.table_name = comments.table_name AND cols.column_name = comments.column_name ORDER BY cols.column_id [0m
  [1m [36mBstaenderungen Load (2.0ms) [0m  [1m [34mSELECT  "BSTAENDERUNGENS".* FROM "BSTAENDERUNGENS" WHERE "BSTAENDERUNGENS"."BSNR" = :a1 AND ROWNUM <= :a2 [0m  [["bsnr", "23825921"], ["LIMIT", 1]]



Yasuo Honda

unread,
Apr 14, 2018, 7:09:15 AM4/14/18
to Oracle enhanced adapter for ActiveRecord
Reply all
Reply to author
Forward
0 new messages