Announcement

Collapse
No announcement yet.
X
  • Filter
  • Time
Clear All
new posts

    SQL related logging correct w.r.t. dbConnection and transaction IDs?

    Hi Isomorphic,

    please see this simple FETCH from my application (6.1p) and the related server log. I stripped out all application related text, as I'm only interested in the log statements.

    If you highlight all occurrences of "2091486909" you'll see that it is mentioned in the context of Connection and Transaction. Is it correct this way? Shouldn't have the transaction some other ID?
    Code:
    === 2018-10-26 10:39:46,654 [ec-6] INFO  SQLDriver - [builtinApplication.null] Executing SQL query on 'Oracle' using connection '2091486909': ...
    === 2018-10-26 10:39:46,659 [ec-6] DEBUG SQLDriver - Freeing SQLDriver dbConnection 2091486909 for SQLDriver instance 138205481
    === 2018-10-26 10:39:46,672 [ec-6] DEBUG SQLTransaction - [builtinApplication.null] Started new Oracle transaction "2091486909"
    === 2018-10-26 10:39:47,049 [ec-6] DEBUG SQLTransaction - Committing Oracle transaction "2091486909"
    === 2018-10-26 10:39:47,050 [ec-6] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  hashcode "2091486909"
    === 2018-10-26 10:39:47,050 [ec-6] DEBUG SQLTransaction - Ending Oracle transaction "2091486909"
    Code:
    === 2018-10-26 10:39:46,652 [ec-6] DEBUG RPCManager - Request #1 (DSRequest) payload: {
        criteria:{
            operator:"and",
            _constructor:"AdvancedCriteria",
            criteria:[
    .....    },
        operationConfig:{
    .....    },
        startRow:0,
        endRow:1000,
    .....
    
    === 2018-10-26 10:39:46,652 [ec-6] DEBUG AppBase - [builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
    === 2018-10-26 10:39:46,652 [ec-6] DEBUG AppBase - [builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
    === 2018-10-26 10:39:46,653 [ec-6] INFO  SQLDataSource - [builtinApplication.null] Performing update operation with ...
    === 2018-10-26 10:39:46,654 [ec-6] INFO  SQLDriver - [builtinApplication.null] DSRequest has no DSTransaction set, when testing if we should join a transaction - transaction will not be joined
    === 2018-10-26 10:39:46,654 [ec-6] INFO  SQLDriver - [builtinApplication.null] Executing SQL query on 'Oracle' using connection '2091486909': ...
    === 2018-10-26 10:39:46,659 [ec-6] WARN  SQLDataSource - [builtinApplication.null] update operation affected no rows
    === 2018-10-26 10:39:46,659 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1155
    === 2018-10-26 10:39:46,659 [ec-6] DEBUG SQLDriver - Freeing SQLDriver dbConnection 2091486909 for SQLDriver instance 138205481
    === 2018-10-26 10:39:46,660 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1155
    === 2018-10-26 10:39:46,660 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1155
    === 2018-10-26 10:39:46,660 [ec-6] INFO  LMSIDACall - Performing 1 operation(s)
    === 2018-10-26 10:39:46,670 [ec-6] DEBUG AppBase - [builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
    === 2018-10-26 10:39:46,670 [ec-6] DEBUG AppBase - [builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
    === 2018-10-26 10:39:46,671 [ec-6] INFO  SQLDataSource - [builtinApplication.null] Performing fetch operation with ...
    === 2018-10-26 10:39:46,671 [ec-6] INFO  SQLDataSource - [builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause$defaultAnsiJoinClause WHERE $defaultWhereClause
    === 2018-10-26 10:39:46,671 [ec-6] INFO  SQLDataSource - [builtinApplication.null] 1175: Executing SQL query on 'Oracle': ...
    === 2018-10-26 10:39:46,672 [ec-6] DEBUG SQLTransaction - [builtinApplication.null] Started new Oracle transaction "2091486909"
    === 2018-10-26 10:39:46,672 [ec-6] DEBUG SQLDataSource - [builtinApplication.null] Setting DSRequest as being part of a transaction
    === 2018-10-26 10:39:46,672 [ec-6] INFO  SQLDriver - [builtinApplication.null] Executing SQL query on 'Oracle' using connection '2091486909': SELECT ...
    === 2018-10-26 10:39:46,688 [ec-6] INFO  DSResponse - DSResponse: List with 12 items
    === 2018-10-26 10:39:46,689 [ec-6] DEBUG AppBase - [builtinApplication.myFetch] No userTypes defined, allowing anyone access to all operations for this application
    === 2018-10-26 10:39:46,689 [ec-6] DEBUG AppBase - [builtinApplication.myFetch] No public zero-argument method named '_myFetch' found, performing generic datasource operation
    === 2018-10-26 10:39:46,689 [ec-6] INFO  SQLDataSource - [builtinApplication.myFetch] Performing fetch operation with ...
    === 2018-10-26 10:39:46,696 [ec-6] DEBUG SQLDataSource - [builtinApplication.myFetch] DataSource 1414 acquired SQLDriver instance 207474391 during initialization
    === 2018-10-26 10:39:46,698 [ec-6] INFO  SQLDataSource - [builtinApplication.myFetch] derived query: SELECT ...
    === 2018-10-26 10:39:46,699 [ec-6] DEBUG SQLDataSource - [builtinApplication.myFetch] Executing row count query: SELECT COUNT(*) ...
    === 2018-10-26 10:39:46,701 [ec-6] DEBUG SQLDataSource - [builtinApplication.myFetch] Eval'd row count query: SELECT COUNT(*) ...
    === 2018-10-26 10:39:46,701 [ec-6] DEBUG SQLDataSource - [builtinApplication.myFetch] Setting DSRequest as being part of a transaction
    === 2018-10-26 10:39:46,701 [ec-6] INFO  SQLDriver - [builtinApplication.myFetch] Executing SQL query on 'Oracle' using connection '2091486909': SELECT COUNT(*) ...
    === 2018-10-26 10:39:46,806 [ec-6] DEBUG SQLDataSource - [builtinApplication.myFetch] JDBC driver windowed select rows 0->1000, result size 1000. Query: SELECT ...
    === 2018-10-26 10:39:46,806 [ec-6] DEBUG SQLDataSource - [builtinApplication.myFetch] Setting DSRequest as being part of a transaction
    === 2018-10-26 10:39:47,047 [ec-6] DEBUG SQLDataSource - [builtinApplication.myFetch] Using paging strategy 'jdbcScroll' - scrolling to absolute position 1
    === 2018-10-26 10:39:47,047 [ec-6] DEBUG SQLDataSource - [builtinApplication.myFetch] Scrolling / positioning took 0ms
    === 2018-10-26 10:39:47,049 [ec-6] INFO  DSResponse - DSResponse: List with 3 items
    === 2018-10-26 10:39:47,049 [ec-6] INFO  DSResponse - DSResponse: List with 3 items
    === 2018-10-26 10:39:47,049 [ec-6] DEBUG RPCManager - Content type for RPC transaction: text/plain; charset=UTF-8
    === 2018-10-26 10:39:47,049 [ec-6] DEBUG SQLTransaction - Committing Oracle transaction "2091486909"
    === 2018-10-26 10:39:47,050 [ec-6] DEBUG RPCManager - DMI response, dropExtraFields: true
    === 2018-10-26 10:39:47,050 [ec-6] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  hashcode "2091486909"
    === 2018-10-26 10:39:47,050 [ec-6] DEBUG SQLTransaction - Ending Oracle transaction "2091486909"
    === 2018-10-26 10:39:47,051 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 862
    === 2018-10-26 10:39:47,051 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1201
    === 2018-10-26 10:39:47,051 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1201
    === 2018-10-26 10:39:47,051 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1395
    === 2018-10-26 10:39:47,051 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1395
    === 2018-10-26 10:39:47,051 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1189
    === 2018-10-26 10:39:47,051 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1189
    === 2018-10-26 10:39:47,051 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 823
    === 2018-10-26 10:39:47,051 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 823
    === 2018-10-26 10:39:47,051 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1188
    === 2018-10-26 10:39:47,051 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1188
    === 2018-10-26 10:39:47,051 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 292
    === 2018-10-26 10:39:47,052 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 292
    === 2018-10-26 10:39:47,052 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1414
    === 2018-10-26 10:39:47,052 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1396
    === 2018-10-26 10:39:47,052 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1396
    === 2018-10-26 10:39:47,052 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 748
    === 2018-10-26 10:39:47,052 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 748
    === 2018-10-26 10:39:47,052 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1175
    === 2018-10-26 10:39:47,052 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1175
    === 2018-10-26 10:39:47,052 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 862
    === 2018-10-26 10:39:47,052 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 862
    === 2018-10-26 10:39:47,052 [ec-6] DEBUG SQLTransaction - getConnection() looked for transactional connection for Oracle:  (connection is null)
    === 2018-10-26 10:39:47,052 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1175
    === 2018-10-26 10:39:47,052 [ec-6] DEBUG SQLDataSource - About to clear SQLDriver state for DS instance 1414
    === 2018-10-26 10:39:47,052 [ec-6] INFO  Compression - /lms/lms/sc/IDACall: 8357 -> 1330 bytes
    Thank you & Best regards
    Blama

    #2
    This is all normal, just an Oracle quirk.

    Comment

    Working...
    X