server side error without stack trace

[claudiobosticco]

v13.0p_2024-09-07/Enterprise Deployment

Hello, I'm seeing an exception in the tomcat logs, but I'm having an hard time understanding what's going on as it seems that the exceptions lack the stack trace:

{"@timestamp":"2024-09-30T15:01:13.634Z","log.level":"DEBUG","message":"Invocation threw exception","log.logger":"com.isomorphic.datasource.DataSourceDMI","error.type":"java.lang.NullPointerException","error.message":null,"error.stack_trace":"java.lang.NullPointerException\n"}
{"@timestamp":"2024-09-30T15:01:13.634Z","log.level":"WARN","message":"dsRequest.execute() failed: ","log.logger":"com.isomorphic.servlet.RequestContext","error.type":"java.lang.NullPointerException","error.message":null,"error.stack_trace":"java.lang.NullPointerException\n"}

do you think that possibly there's an exception where the stack trace isn't logged?

do you think there's some specific log which I may try to enable to help debug this problem?

[Isomorphic]

Those are obviously server logs (in JSON format), but they don't look like the server logs that we normally report through our logging system. Do you have some custom logging configuration or logging aggregrator in place?

We definitely include the exception when calling the logging api for the two messages that you list - "Invocation threw an exception" and "dsRequest.execute() failed" - which should cause the exception stack to be included when logged through the default setup.

[claudiobosticco]

Hello, I haven't seen that error after the above post, till today. In that day I configured logging to log also without the json formatting, to exclude a Kibana/Elastic problem.

But I still see a log like this:

2024-11-08T15:46:53,467 INFO DSResponse DSResponse: List with 4 items
2024-11-08T15:46:53,467 DEBUG DSRequest freeOnExecute is false for request of type fetch on DataSource JPC_CONTRATTI_RIGHE - not freeing resources!
2024-11-08T15:46:53,469 DEBUG PoolableDataSourceFactory Activated DataSource 1212 of type 'JPC_VOCI_DI_LISTINO' with hashCode '2106938228'
2024-11-08T15:46:53,469 DEBUG DSRequest Caching instance 1212 of DS 'JPC_VOCI_DI_LISTINO' from DSRequest.getDataSource()
2024-11-08T15:46:53,469 DEBUG DSRequest Caching instance 1212 of DS JPC_VOCI_DI_LISTINO
2024-11-08T15:46:53,469 INFO DSRequest Executing JPC_VOCI_DI_LISTINO.fetch rows: 0->-1 with
criteria: {ID_REC:3025087}
2024-11-08T15:46:53,469 DEBUG DSRequest About to free up resources for request of type fetch on DataSource JPC_VOCI_DI_LISTINO
2024-11-08T15:46:53,469 DEBUG DSRequest Ignoring freeResources call because this is not a primary request!
2024-11-08T15:46:53,469 DEBUG DataSourceDMI Invocation threw exception
java.lang.NullPointerException: null
2024-11-08T15:46:53,469 DEBUG DSRequest freeOnExecute is false for request of type fetch on DataSource JPC_CONTRATTI_RIGHE - not freeing resources!
2024-11-08T15:46:53,469 DEBUG DataSourceDMI Invocation threw exception
java.lang.NullPointerException: null
2024-11-08T15:46:53,469 DEBUG DSRequest About to free up resources for request of type fetch on DataSource JPC_FATTURE_CONTRATTI
2024-11-08T15:46:53,469 DEBUG DSRequest Ignoring freeResources call because this is not a primary request!
2024-11-08T15:46:53,469 WARN RequestContext dsRequest.execute() failed:
java.lang.NullPointerException: null
2024-11-08T15:46:53,470 DEBUG DSRequest Ignoring freeQueueResources call because this is not a primary request!
2024-11-08T15:46:53,470 DEBUG SQLTransaction getConnection() looked for transactional connection for dbJpcEP: hashcode "1078392065"
2024-11-08T15:46:53,470 DEBUG SQLTransaction Ending dbJpcEP transaction "1078392065"
2024-11-08T15:46:53,471 DEBUG SQLConnectionManager About to close PoolGuardConnectionWrapper with hashcode "1078392065"
2024-11-08T15:46:53,471 DEBUG SQLDataSource About to clear SQLDriver state for DS instance 1193
2024-11-08T15:46:53,472 DEBUG DataSource JPC_CONTRATTI_BASEisSandboxEligible?: false
2024-11-08T15:46:53,472 DEBUG DataSource JPC_CONTRATTI_BASE isCacheable?: true
2024-11-08T15:46:53,472 DEBUG PoolableDataSourceFactory Cleared and passivated DataSource 18821 of type 'JPC_CONTRATTI_BASE' with hashCode '1084658294'
2024-11-08T15:46:53,472 DEBUG SQLDataSource About to clear SQLDriver state for DS instance 3660
2024-11-08T15:46:53,472 DEBUG DataSource JPC_CONTRATTI isCacheable?: true
2024-11-08T15:46:53,472 DEBUG PoolableDataSourceFactory Cleared and passivated DataSource 3660 of type 'JPC_CONTRATTI' with hashCode '493871013'
2024-11-08T15:46:53,472 DEBUG SQLDataSource About to clear SQLDriver state for DS instance 18367
2024-11-08T15:46:53,473 DEBUG DataSource LEG_PRODOTTI_ORDINE isCacheable?: true
2024-11-08T15:46:53,473 DEBUG PoolableDataSourceFactory Cleared and passivated DataSource 18367 of type 'LEG_PRODOTTI_ORDINE' with hashCode '794334015'
2024-11-08T15:46:53,473 DEBUG SQLDataSource About to clear SQLDriver state for DS instance 18458
2024-11-08T15:46:53,473 DEBUG DataSource LEG_FASCE_PREZZO isCacheable?: true
2024-11-08T15:46:53,473 DEBUG PoolableDataSourceFactory Cleared and passivated DataSource 18458 of type 'LEG_FASCE_PREZZO' with hashCode '1667336421'
2024-11-08T15:46:53,473 DEBUG DataSource JPC_CONTRATTI_RIGHE_BASEisSandboxEligible?: false
2024-11-08T15:46:53,473 DEBUG DataSource JPC_CONTRATTI_RIGHE_BASE isCacheable?: true
2024-11-08T15:46:53,473 DEBUG PoolableDataSourceFactory Cleared and passivated DataSource 18822 of type 'JPC_CONTRATTI_RIGHE_BASE' with hashCode '877785728'
2024-11-08T15:46:53,473 DEBUG SQLDataSource About to clear SQLDriver state for DS instance 1197
2024-11-08T15:46:53,473 DEBUG DataSource JPC_CONTRATTI_RIGHE isCacheable?: true
2024-11-08T15:46:53,473 DEBUG PoolableDataSourceFactory Cleared and passivated DataSource 1197 of type 'JPC_CONTRATTI_RIGHE' with hashCode '356246842'
2024-11-08T15:46:53,473 DEBUG SQLDataSource About to clear SQLDriver state for DS instance 1212
2024-11-08T15:46:53,474 DEBUG DataSource JPC_VOCI_DI_LISTINO isCacheable?: true
2024-11-08T15:46:53,474 DEBUG PoolableDataSourceFactory Cleared and passivated DataSource 1212 of type 'JPC_VOCI_DI_LISTINO' with hashCode '2106938228'
2024-11-08T15:46:53,474 DEBUG SQLDataSource About to clear SQLDriver state for DS instance 1193
2024-11-08T15:46:53,474 DEBUG DataSource JPC_FATTURE_CONTRATTI isCacheable?: true
2024-11-08T15:46:53,474 DEBUG PoolableDataSourceFactory Cleared and passivated DataSource 1193 of type 'JPC_FATTURE_CONTRATTI' with hashCode '1830967485'
2024-11-08T15:46:53,474 DEBUG SQLTransaction getConnection() looked for transactional connection for dbJpcEP: (connection is null)
2024-11-08T15:46:53,474 DEBUG SQLDataSource About to clear SQLDriver state for DS instance 3660
2024-11-08T15:46:53,474 DEBUG SQLTransaction getConnection() looked for transactional connection for dbJpcEP: (connection is null)
2024-11-08T15:46:53,474 DEBUG SQLDataSource About to clear SQLDriver state for DS instance 1197
2024-11-08T15:46:53,474 DEBUG DSRequest Ignoring freeQueueResources call because this is not a primary request!
2024-11-08T15:46:53,474 DEBUG DSRequest Ignoring freeResources call because they have already been freed
2024-11-08T15:46:53,474 DEBUG DSRequest Ignoring freeQueueResources call because they have already been freed
2024-11-08T15:46:53,474 DEBUG DSRequest Ignoring freeResources call because they have already been freed
2024-11-08T15:46:53,474 DEBUG DSRequest Ignoring freeQueueResources call because they have already been freed
2024-11-08T15:46:53,474 DEBUG DSRequest Ignoring freeResources call because they have already been freed
2024-11-08T15:46:53,474 DEBUG DSRequest Ignoring freeQueueResources call because they have already been freed
2024-11-08T15:46:53,474 DEBUG DSRequest Ignoring freeResources call because they have already been freed
2024-11-08T15:46:53,474 DEBUG DSRequest Ignoring freeQueueResources call because they have already been freed

where you can see 3 NPE without a stack trace.

I don't have a custom logging, and I'm using log4j2 with slf4j. SmartClient version now is 13.0-p20240929

Do you have any idea what might be happening?

I suspect there might be some code where the requirement mentioned in this post https://forums.smartclient.com/forum...ntext-instance is not met. What kind of issues could this cause?

[Isomorphic]

Misuse of RequestContext.instance() would be expected to introduce concurrency issues, not squelched stack traces.

Log4j can be configured to omit stack traces, for example, by removing the stack trace from the PatternLayout for a given log category. The JVM could also be configured to omit traces.

Here's ChatGPT's take (covering the above and some more obscure possibilities):

https://chatgpt.com/share/672e8c12-e...4-676a0e156b83

Also, is this an error you can reliably reproduce? Because the error seems to happen inside of your DMI code, so you could add a try/catch there to get direct access to the Exception and see if it is somehow an Exception with no stack.