Skip to content

Commit

Permalink
Improve BGS validation error logging (#12939)
Browse files Browse the repository at this point in the history 
BGS sometimes returns errors containing an enormous stacktrace with an oracle error. This PR logs the oracle error message and excludes everything else. These oracle errors start with the signature `ORA-` and are bookended by a `prepstmnt` clause. See `spec/fixtures/bgs/bgs_oracle_error.txt` for an example. We want to log these errors separately because the original error message is so long that it obscures its only relevant information and actually breaks Sentry's UI.
  • Loading branch information
@data-doge
data-doge authored Jun 13, 2023
1 parent dece55a commit 85518c8
Show file tree
Hide file tree
Showing 3 changed files with 199 additions and 0 deletions.
20 changes: 20 additions & 0 deletions lib/bgs/exceptions/bgs_errors.rb
View file
Original file line number Diff line number Diff line change
Expand Up @@ -27,6 +27,7 @@ def notify_of_service_exception(error, method, attempt = nil, status = :error)

return log_message_to_sentry(msg, :warn, context, tags) if status == :warn

log_oracle_errors!(error:)
log_exception_to_sentry(error, context, tags)
raise_backend_exception('BGS_686c_SERVICE_403', self.class, error)
end
Expand All @@ -41,6 +42,25 @@ def raise_backend_exception(key, source, error)

raise exception
end

private

# BGS sometimes returns errors containing an enormous stacktrace with an oracle error. This method logs the oracle
# error message and excludes everything else. These oracle errors start with the signature `ORA-` and are
# bookended by a `prepstmnt` clause. See `spec/fixtures/bgs/bgs_oracle_error.txt` for an example. We want to log
# these errors separately because the original error message is so long that it obscures its only relevant
# information and actually breaks Sentry's UI.
def log_oracle_errors!(error:)
oracle_error_match_data = error.message.match(/ORA-.+?(?=\s*{prepstmnt)/m)
if oracle_error_match_data&.length&.positive?
log_message_to_sentry(
oracle_error_match_data[0],
:error,
{ icn: @user[:icn] },
{ team: 'vfs-ebenefits' }
)
end
end
end
end
end
123 changes: 123 additions & 0 deletions spec/fixtures/bgs/bgs_oracle_error.txt
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,123 @@
(ns0:Server) EJB Exception: : <openjpa-1.1.1-SNAPSHOT-r422266:1445923 fatal general error> org.apache.openjpa.persistence.PersistenceException: The transaction has been rolled back. See the nested exceptions for details on the errors that occurred.
at org.apache.openjpa.kernel.BrokerImpl.newFlushException(BrokerImpl.java:2170)
at org.apache.openjpa.kernel.BrokerImpl.flush(BrokerImpl.java:2017)
at org.apache.openjpa.kernel.BrokerImpl.flushSafe(BrokerImpl.java:1915)
at org.apache.openjpa.kernel.BrokerImpl.flush(BrokerImpl.java:1686)
at org.apache.openjpa.kernel.QueryImpl.isInMemory(QueryImpl.java:955)
at org.apache.openjpa.kernel.QueryImpl.execute(QueryImpl.java:795)
at org.apache.openjpa.kernel.QueryImpl.updateAll(QueryImpl.java:883)
at kodo.kernel.KodoQuery.updateAll(KodoQuery.java:67)
at org.apache.openjpa.kernel.QueryImpl.updateAll(QueryImpl.java:879)
at kodo.kernel.KodoQuery.updateAll(KodoQuery.java:63)
at org.apache.openjpa.kernel.DelegatingQuery.updateAll(DelegatingQuery.java:565)
at org.apache.openjpa.persistence.QueryImpl.executeUpdate(QueryImpl.java:322)
at sun.reflect.GeneratedMethodAccessor3781.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at weblogic.persistence.InterceptingInvocationHandlerImpl.invoke(InterceptingInvocationHandlerImpl.java:24)
at com.sun.proxy.$Proxy879.executeUpdate(Unknown Source)
at gov.va.vba.benefits.vdc.util.Util.clearDBGlobals(Unknown Source)
at gov.va.vba.vonapp.services.personService.VnpPersonWebServiceBean.vnpPersonCreate(Unknown Source)
at sun.reflect.GeneratedMethodAccessor6329.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.bea.core.repackaged.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
at com.bea.core.repackaged.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)
at com.bea.core.repackaged.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at com.oracle.pitchfork.intercept.MethodInvocationInvocationContext.proceed(MethodInvocationInvocationContext.java:101)
at com.oracle.pitchfork.intercept.JeeInterceptorInterceptor.invoke(JeeInterceptorInterceptor.java:101)
at com.bea.core.repackaged.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at com.oracle.pitchfork.intercept.MethodInvocationInvocationContext.proceed(MethodInvocationInvocationContext.java:101)
at org.jboss.weld.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:73)
at org.jboss.weld.ejb.SessionBeanInterceptor.aroundInvoke(SessionBeanInterceptor.java:52)
at sun.reflect.GeneratedMethodAccessor449.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.oracle.pitchfork.intercept.JeeInterceptorInterceptor.invoke(JeeInterceptorInterceptor.java:94)
at com.bea.core.repackaged.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at com.bea.core.repackaged.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:136)
at com.bea.core.repackaged.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:124)
at com.bea.core.repackaged.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at com.bea.core.repackaged.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
at com.sun.proxy.$Proxy928.vnpPersonCreate(Unknown Source)
at gov.va.vba.vonapp.services.personService.VnpPersonWebServiceBean_mfemv4_WSOImpl.__WL_invoke(Unknown Source)
at weblogic.ejb.container.internal.WSOMethodInvoker.invoke(WSOMethodInvoker.java:24)
at gov.va.vba.vonapp.services.personService.VnpPersonWebServiceBean_mfemv4_WSOImpl.__WL_vnpPersonCreate_WS(Unknown Source)
at sun.reflect.GeneratedMethodAccessor6328.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at weblogic.wsee.server.ejb.WsEjb.invoke(WsEjb.java:55)
at weblogic.wsee.jaxws.WLSEjbInstanceResolver$WLSEjbInvoker.invoke(WLSEjbInstanceResolver.java:196)
at weblogic.wsee.jaxws.WLSInstanceResolver$WLSInvoker.invoke(WLSInstanceResolver.java:93)
at com.sun.xml.ws.server.InvokerTube$2.invoke(InvokerTube.java:149)
at com.sun.xml.ws.server.sei.SEIInvokerTube.processRequest(SEIInvokerTube.java:88)
at com.sun.xml.ws.api.pipe.Fiber.__doRun(Fiber.java:1136)
at com.sun.xml.ws.api.pipe.Fiber._doRun(Fiber.java:1050)
at com.sun.xml.ws.api.pipe.Fiber.doRun(Fiber.java:1019)
at com.sun.xml.ws.api.pipe.Fiber.runSync(Fiber.java:877)
at com.sun.xml.ws.server.WSEndpointImpl$2.process(WSEndpointImpl.java:419)
at com.sun.xml.ws.transport.http.HttpAdapter$HttpToolkit.handle(HttpAdapter.java:868)
at com.sun.xml.ws.transport.http.HttpAdapter.handle(HttpAdapter.java:422)
at com.sun.xml.ws.transport.http.servlet.ServletAdapter.handle(ServletAdapter.java:169)
at weblogic.wsee.jaxws.WLSServletAdapter.handle(WLSServletAdapter.java:246)
at weblogic.wsee.jaxws.HttpServletAdapter$AuthorizedInvoke.run(HttpServletAdapter.java:667)
at weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:386)
at weblogic.security.service.SecurityManager.runAs(SecurityManager.java:163)
at weblogic.wsee.util.ServerSecurityHelper.authenticatedInvoke(ServerSecurityHelper.java:108)
at weblogic.wsee.jaxws.HttpServletAdapter$3.run(HttpServletAdapter.java:286)
at weblogic.wsee.jaxws.HttpServletAdapter.post(HttpServletAdapter.java:295)
at weblogic.wsee.jaxws.JAXWSServlet.doRequest(JAXWSServlet.java:128)
at weblogic.servlet.http.AbstractAsyncServlet.service(AbstractAsyncServlet.java:103)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:295)
at weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:260)
at weblogic.servlet.internal.StubSecurityHelper.invokeServlet(StubSecurityHelper.java:137)
at weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:353)
at weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:250)
at weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.wrapRun(WebAppServletContext.java:3796)
at weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.run(WebAppServletContext.java:3766)
at weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:344)
at weblogic.security.service.SecurityManager.runAsForUserCode(SecurityManager.java:197)
at weblogic.servlet.provider.WlsSecurityProvider.runAsForUserCode(WlsSecurityProvider.java:203)
at weblogic.servlet.provider.WlsSubjectHandle.run(WlsSubjectHandle.java:71)
at weblogic.servlet.internal.WebAppServletContext.doSecuredExecute(WebAppServletContext.java:2454)
at weblogic.servlet.internal.WebAppServletContext.securedExecute(WebAppServletContext.java:2302)
at weblogic.servlet.internal.WebAppServletContext.execute(WebAppServletContext.java:2280)
at weblogic.servlet.internal.ServletRequestImpl.runInternal(ServletRequestImpl.java:1721)
at weblogic.servlet.internal.ServletRequestImpl.run(ServletRequestImpl.java:1681)
at weblogic.servlet.provider.ContainerSupportProviderImpl$WlsRequestExecutor.run(ContainerSupportProviderImpl.java:272)
at weblogic.invocation.ComponentInvocationContextManager._runAs(ComponentInvocationContextManager.java:352)
at weblogic.invocation.ComponentInvocationContextManager.runAs(ComponentInvocationContextManager.java:337)
at weblogic.work.LivePartitionUtility.doRunWorkUnderContext(LivePartitionUtility.java:57)
at weblogic.work.PartitionUtility.runWorkUnderContext(PartitionUtility.java:41)
at weblogic.work.SelfTuningWorkManagerImpl.runWorkUnderContext(SelfTuningWorkManagerImpl.java:655)
at weblogic.work.ExecuteThread.execute(ExecuteThread.java:420)
at weblogic.work.ExecuteThread.run(ExecuteThread.java:360)
Caused by: <openjpa-1.1.1-SNAPSHOT-r422266:1445923 nonfatal general error> org.apache.openjpa.persistence.PersistenceException: ORA-12899: value too large for column "CORPPROD"."VNP_PERSON"."MIDDLE_NM" (actual: 52, maximum: 30)
{prepstmnt 121207984 INSERT INTO VNP_PERSON (VNP_PTCPNT_ID, BIRTH_CITY_NM, BIRTH_CNTRY_NM, BIRTH_STATE_CD, BRTHDY_DT, CMPTNY_DECN_TYPE_CD, DEATH_CITY_CNTRY_NM, DEATH_CNTRY_NM, DEATH_DT, DEATH_STATE_CD, DEP_NBR, EMP_IND, ENTLMT_TYPE_CD, ETHNIC_TYPE_CD, EVER_MARIED_IND, FID_DECN_CATEGY_TYPE_CD, FILE_NBR, FIRST_NM, FIRST_NM_KEY, FRGN_SVC_NBR, GENDER_CD, JRN_DT, JRN_LCTN_ID, JRN_OBJ_ID, JRN_STATUS_TYPE_CD, JRN_USER_ID, LAST_NM, LAST_NM_KEY, LGY_ENTLMT_TYPE_CD, MARTL_STATUS_TYPE_CD, MIDDLE_NM, MIDDLE_NM_KEY, MLTY_PERSON_IND, MONTHS_PRESNT_EMPLYR_NBR, NET_WORTH_AMT, NO_SSN_REASON_TYPE_CD, OCPTN_TXT, PERSON_DEATH_CAUSE_TYPE_NM, PERSON_TYPE_NM, POTNTL_DNGRS_IND, RACE_TYPE_NM, SBSTNC_AMT, SEROUS_EMPLMT_HNDCAP_IND, SLTTN_TYPE_NM, SPINA_BIFIDA_IND, SPOUSE_NUM, SSN_NBR, SSN_VRFCTN_STATUS_TYPE_CD, SUFFIX_NM, SUFFIX_NM_KEY, TAX_ABTMNT_CD, TERMNL_DIGIT_NBR, TITLE_TXT, VET_IND, VET_TYPE_NM, VNP_PROC_ID, VNP_SCHOOL_CHILD_IND, VNP_SRUSLY_DSABLD_IND, YEARS_PRESNT_EMPLYR_NBR) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) [params=(long) 11111111, (String) Foo, (null) null, (String) HI, (Date) 2008-06-20, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (String) N, (null) null, (null) null, (String) Bar, (null) null, (null) null, (null) null, (Timestamp) 2023-05-16 00:00:00.0, (String) 281, (String) VAgovAPI, (String) U, (String) VAgovAPI, (String) Baz, (null) null, (null) null, (null) null, (String) Foo, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (String) 11111111, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (long) 1111111, (null) null, (String) Y, (null) null]} [code=12899, state=72000]
FailedObject: gov.va.vba.vonapp.entities.VnpPerson@7482ee7b
at org.apache.openjpa.jdbc.sql.DBDictionary.narrow(DBDictionary.java:4207)
at org.apache.openjpa.jdbc.sql.DBDictionary.newStoreException(DBDictionary.java:4171)
at org.apache.openjpa.jdbc.sql.SQLExceptions.getStore(SQLExceptions.java:102)
at org.apache.openjpa.jdbc.sql.SQLExceptions.getStore(SQLExceptions.java:72)
at kodo.jdbc.kernel.BatchingPreparedStatementManager.flushInternal(BatchingPreparedStatementManager.java:214)
at kodo.jdbc.kernel.BatchingPreparedStatementManager.flushInternal(BatchingPreparedStatementManager.java:149)
at kodo.jdbc.kernel.BatchingPreparedStatementManager.flush(BatchingPreparedStatementManager.java:72)
at kodo.jdbc.kernel.AutoOrderUpdateManager.flush(AutoOrderUpdateManager.java:84)
at kodo.jdbc.kernel.ConstraintUpdateManager.flush(ConstraintUpdateManager.java:68)
at org.apache.openjpa.jdbc.kernel.AbstractUpdateManager.flush(AbstractUpdateManager.java:89)
at org.apache.openjpa.jdbc.kernel.AbstractUpdateManager.flush(AbstractUpdateManager.java:72)
at org.apache.openjpa.jdbc.kernel.JDBCStoreManager.flush(JDBCStoreManager.java:569)
at org.apache.openjpa.kernel.DelegatingStoreManager.flush(DelegatingStoreManager.java:130)
at org.apache.openjpa.datacache.DataCacheStoreManager.flush(DataCacheStoreManager.java:571)
at org.apache.openjpa.kernel.DelegatingStoreManager.flush(DelegatingStoreManager.java:130)
... 93 more
Caused by: org.apache.openjpa.lib.jdbc.ReportingSQLException: ORA-12899: value too large for column "CORPPROD"."VNP_PERSON"."MIDDLE_NM" (actual: 52, maximum: 30)
{prepstmnt 121207984 INSERT INTO VNP_PERSON (VNP_PTCPNT_ID, BIRTH_CITY_NM, BIRTH_CNTRY_NM, BIRTH_STATE_CD, BRTHDY_DT, CMPTNY_DECN_TYPE_CD, DEATH_CITY_CNTRY_NM, DEATH_CNTRY_NM, DEATH_DT, DEATH_STATE_CD, DEP_NBR, EMP_IND, ENTLMT_TYPE_CD, ETHNIC_TYPE_CD, EVER_MARIED_IND, FID_DECN_CATEGY_TYPE_CD, FILE_NBR, FIRST_NM, FIRST_NM_KEY, FRGN_SVC_NBR, GENDER_CD, JRN_DT, JRN_LCTN_ID, JRN_OBJ_ID, JRN_STATUS_TYPE_CD, JRN_USER_ID, LAST_NM, LAST_NM_KEY, LGY_ENTLMT_TYPE_CD, MARTL_STATUS_TYPE_CD, MIDDLE_NM, MIDDLE_NM_KEY, MLTY_PERSON_IND, MONTHS_PRESNT_EMPLYR_NBR, NET_WORTH_AMT, NO_SSN_REASON_TYPE_CD, OCPTN_TXT, PERSON_DEATH_CAUSE_TYPE_NM, PERSON_TYPE_NM, POTNTL_DNGRS_IND, RACE_TYPE_NM, SBSTNC_AMT, SEROUS_EMPLMT_HNDCAP_IND, SLTTN_TYPE_NM, SPINA_BIFIDA_IND, SPOUSE_NUM, SSN_NBR, SSN_VRFCTN_STATUS_TYPE_CD, SUFFIX_NM, SUFFIX_NM_KEY, TAX_ABTMNT_CD, TERMNL_DIGIT_NBR, TITLE_TXT, VET_IND, VET_TYPE_NM, VNP_PROC_ID, VNP_SCHOOL_CHILD_IND, VNP_SRUSLY_DSABLD_IND, YEARS_PRESNT_EMPLYR_NBR) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) [params=(long) 11111111, (String) Foo, (null) null, (String) HI, (Date) 2008-06-20, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (String) N, (null) null, (null) null, (String) Bar, (null) null, (null) null, (null) null, (Timestamp) 2023-05-16 00:00:00.0, (String) 281, (String) VAgovAPI, (String) U, (String) VAgovAPI, (String) Baz, (null) null, (null) null, (null) null, (String) Foo, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (String) 11111111, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (null) null, (long) 1111111, (null) null, (String) Y, (null) null]} [code=12899, state=72000]
at org.apache.openjpa.lib.jdbc.LoggingConnectionDecorator.wrap(LoggingConnectionDecorator.java:192)
at org.apache.openjpa.lib.jdbc.LoggingConnectionDecorator.access$700(LoggingConnectionDecorator.java:57)
at org.apache.openjpa.lib.jdbc.LoggingConnectionDecorator$LoggingConnection$LoggingPreparedStatement.executeUpdate(LoggingConnectionDecorator.java:866)
at org.apache.openjpa.lib.jdbc.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:269)
at org.apache.openjpa.jdbc.kernel.JDBCStoreManager$CancelPreparedStatement.executeUpdate(JDBCStoreManager.java:1453)
at kodo.jdbc.kernel.BatchingPreparedStatementManager.flushInternal(BatchingPreparedStatementManager.java:208)
... 103 more
56 changes: 56 additions & 0 deletions spec/lib/bgs/exceptions/bgs_errors_spec.rb
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,56 @@
# frozen_string_literal: true

require 'rails_helper'
require 'bgs/exceptions/bgs_errors'

RSpec.describe BGS::Exceptions::BGSErrors do
let(:dummy_class) do
Class.new do
include BGS::Exceptions::BGSErrors
attr_reader :user

def initialize
@user = { icn: '1234' }
end
end
end
let(:dummy_instance) { dummy_class.new }

describe '#notify_of_service_exception' do
context 'large stacktrace with oracle error message and PII returned' do
it 'logs the oracle error message to Sentry, but not the stacktrace or PII' do
error_message = File.read('spec/fixtures/bgs/bgs_oracle_error.txt')
dummy_error = StandardError.new(error_message)
expect(dummy_instance).to receive(:log_message_to_sentry).with(
'ORA-12899: value too large for column "CORPPROD"."VNP_PERSON"."MIDDLE_NM" (actual: 52, maximum: 30)',
:error,
{ icn: '1234' },
{ team: 'vfs-ebenefits' }
)
expect do
dummy_instance.notify_of_service_exception(dummy_error, 'dummy_method')
end.to raise_error(BGS::ServiceException)
end
end

context 'error not related to oracle' do
it "raises a BGS::ServiceException with BGS's raw error message" do
dummy_error = StandardError.new('(ns0:Server) insertBenefitClaim: City is null')
expect(dummy_instance).not_to receive(:log_message_to_sentry)
expect do
dummy_instance.notify_of_service_exception(dummy_error, 'dummy_method')
end.to raise_error(BGS::ServiceException)
end
end

context 'no error message' do
it 'raises a BGS::ServiceException' do
dummy_error = StandardError.new
expect(dummy_instance).not_to receive(:log_message_to_sentry)
expect do
dummy_instance.notify_of_service_exception(dummy_error, 'dummy_method')
end.to raise_error(BGS::ServiceException)
end
end
end
end

0 comments on commit 85518c8

Please sign in to comment.