Re: user_id 0 in V$ACTIVE_SESSION_HISTORY/DBA_HIST_ACTIVE_SESS_HISTORY

From: Mikhail Velikikh <mvelikikh_at_gmail.com>
Date: Sun, 27 Dec 2020 00:17:30 +0000
Message-ID: <CALe4HpmhCFALYEjsS1TwanNUHZPZWYO7vUmRkCc99L6gA2f=bQ_at_mail.gmail.com>



Hi Dimitre,

Once I have seen it in an environment with ORDS/APEX. Another time it was due to failed JDBC connections. Since ORDS uses JDBC, I think it is mostly JDBC related rather than OAuth authentication itself.

I can reproduce it with the following Java class that uses invalid database credentials so as to receive ORA-1017:

import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.SQLException;

public class JDBCExample {

    public static void main(String[] args) {

        //
https://docs.oracle.com/javase/8/docs/api/java/sql/package-summary.html#package.description

        // auto java.sql.Driver discovery -- no longer need to load a java.sql.Driver class via Class.forName

        // register JDBC driver, optional since java 1.6
        /*try {
            Class.forName("oracle.jdbc.driver.OracleDriver");

} catch (ClassNotFoundException e) {
e.printStackTrace(); }*/ // Oracle SID = orcl , find yours in tnsname.ora try (Connection conn = DriverManager.getConnection( "jdbc:oracle:thin:_at_//localhost/XEPDB1", "x", "y")) { if (conn != null) { System.out.println("Connected to the database!"); } else { System.out.println("Failed to make connection!"); }
} catch (SQLException e) {
System.err.format("SQL State: %s\n%s", e.getSQLState(), e.getMessage());
} catch (Exception e) {
e.printStackTrace(); }

    }
}

I enabled SQL*Net server trace, and I also fired a script polling v$session.
That is what I got in v$session - user#=0, top_level_call#=115 which corresponds to OAUTH in my XE database.

<ROWSET>
  <ROW>
* <SAMPLE_TIME>26-DEC-20 11.52.25.741 PM</SAMPLE_TIME>*

    <SADDR>000000006AAC94D0</SADDR>
    <SID>58</SID>
    <SERIAL_x0023_>47422</SERIAL_x0023_>
    <AUDSID>0</AUDSID>
    <PADDR>000000006AF5F528</PADDR>

* <USER_x0023_>0</USER_x0023_>*
    <COMMAND>0</COMMAND>
    <OWNERID>2147483644</OWNERID>
    <STATUS>ACTIVE</STATUS>
    <SERVER>DEDICATED</SERVER>
    <SCHEMA_x0023_>0</SCHEMA_x0023_>
    <SCHEMANAME>SYS</SCHEMANAME>
    <OSUSER>oracle</OSUSER>
    <PROCESS>1234</PROCESS>
    <MACHINE>localhost.localdomain</MACHINE>
    <PORT>51416</PORT>
    <TERMINAL>unknown</TERMINAL>
    <PROGRAM>JDBC Thin Client</PROGRAM>
    <TYPE>USER</TYPE>
    <SQL_ADDRESS>00</SQL_ADDRESS>
    <SQL_HASH_VALUE>0</SQL_HASH_VALUE>
    <SQL_CHILD_NUMBER>0</SQL_CHILD_NUMBER>
    <PREV_SQL_ADDR>00</PREV_SQL_ADDR>
    <PREV_HASH_VALUE>0</PREV_HASH_VALUE>
    <PREV_CHILD_NUMBER>0</PREV_CHILD_NUMBER>
    <MODULE>JDBC Thin Client</MODULE>
    <MODULE_HASH>2546894660</MODULE_HASH>
    <ACTION_HASH>0</ACTION_HASH>
    <FIXED_TABLE_SEQUENCE>13040999</FIXED_TABLE_SEQUENCE>
    <ROW_WAIT_OBJ_x0023_>-1</ROW_WAIT_OBJ_x0023_>
    <ROW_WAIT_FILE_x0023_>0</ROW_WAIT_FILE_x0023_>
    <ROW_WAIT_BLOCK_x0023_>0</ROW_WAIT_BLOCK_x0023_>
    <ROW_WAIT_ROW_x0023_>0</ROW_WAIT_ROW_x0023_>
* <TOP_LEVEL_CALL_x0023_>115</TOP_LEVEL_CALL_x0023_>*
    <LOGON_TIME>26.12.2020 23:52:24</LOGON_TIME>
    <LAST_CALL_ET>1</LAST_CALL_ET>
    <PDML_ENABLED>NO</PDML_ENABLED>
    <FAILOVER_TYPE>NONE</FAILOVER_TYPE>
    <FAILOVER_METHOD>NONE</FAILOVER_METHOD>
    <FAILED_OVER>NO</FAILED_OVER>
    <PDML_STATUS>DISABLED</PDML_STATUS>
    <PDDL_STATUS>DISABLED</PDDL_STATUS>
    <PQ_STATUS>DISABLED</PQ_STATUS>
    <CURRENT_QUEUE_DURATION>0</CURRENT_QUEUE_DURATION>
    <BLOCKING_SESSION_STATUS>NO HOLDER</BLOCKING_SESSION_STATUS>
    <FINAL_BLOCKING_SESSION_STATUS>NO HOLDER</FINAL_BLOCKING_SESSION_STATUS>
    <SEQ_x0023_>5</SEQ_x0023_>
    <EVENT_x0023_>1381</EVENT_x0023_>

* <EVENT>Failed Logon Delay</EVENT>*
    <P1>100</P1>
    <P1RAW>0000000000000064</P1RAW>
    <P2>0</P2>
    <P2RAW>00</P2RAW>
    <P3>0</P3>
    <P3RAW>00</P3RAW>
    <WAIT_CLASS_ID>1893977003</WAIT_CLASS_ID>
    <WAIT_CLASS_x0023_>0</WAIT_CLASS_x0023_>
    <WAIT_CLASS>Other</WAIT_CLASS>
    <WAIT_TIME>0</WAIT_TIME>
    <SECONDS_IN_WAIT>1</SECONDS_IN_WAIT>
    <STATE>WAITING</STATE>
    <WAIT_TIME_MICRO>628776</WAIT_TIME_MICRO>
    <TIME_REMAINING_MICRO>371224</TIME_REMAINING_MICRO>
    <TIME_SINCE_LAST_WAIT_MICRO>0</TIME_SINCE_LAST_WAIT_MICRO>
    <SERVICE_NAME>xepdb1</SERVICE_NAME>
    <SQL_TRACE>DISABLED</SQL_TRACE>
    <SQL_TRACE_WAITS>FALSE</SQL_TRACE_WAITS>
    <SQL_TRACE_BINDS>FALSE</SQL_TRACE_BINDS>
    <SQL_TRACE_PLAN_STATS>FIRST EXEC</SQL_TRACE_PLAN_STATS>
    <SESSION_EDITION_ID>0</SESSION_EDITION_ID>
    <CREATOR_ADDR>000000006AF5F528</CREATOR_ADDR>
    <CREATOR_SERIAL_x0023_>71</CREATOR_SERIAL_x0023_>
    <SQL_TRANSLATION_PROFILE_ID>0</SQL_TRANSLATION_PROFILE_ID>
    <PGA_TUNABLE_MEM>0</PGA_TUNABLE_MEM>
    <SHARD_DDL_STATUS>DISABLED</SHARD_DDL_STATUS>
    <CON_ID>3</CON_ID>
    <PLSQL_DEBUGGER_CONNECTED>FALSE</PLSQL_DEBUGGER_CONNECTED>
  </ROW>
</ROWSET>

select * from v$toplevelcall where top_level_call#=115;

TOP_LEVEL_CALL# TOP_LEVEL_CALL_NAME
         CON_ID


  • ---------- *115 *OAUTH 0

This is the relevant part of my SQL*Net trace file processed by trcasst:

---> Send 241 bytes - Data packet timestamp=020-12-26 23:52:24.270 Set protocol (TTIPRO)

        Operation 01 (con) Send protocol version=6
        Originating platform: x86_64/Linux 2.4.xx

<--- Received 2684 bytes - Data packet timestamp=020-12-26 23:52:24.843 Set datatypes (TTIDTY)

---> Send 2697 bytes - Data packet timestamp=020-12-26 23:52:24.851 Set datatypes (TTIDTY)

<--- Received 169 bytes - Data packet timestamp=020-12-26 23:52:24.937 Start of user function (TTIFUN)

        Get the session key (OSESSKEY)

---> Send 370 bytes - Data packet timestamp=020-12-26 23:52:24.979 Return opi parameter (TTIRPA)

*<--- Received 1207 bytes - Data packet timestamp=020-12-26 23:52:25.108Start of user function (TTIFUN) Generic authentication call (OAUTH)---> Send 11 bytes - Marker packet timestamp=020-12-26 23:52:26.128 One data byte. Hex character sent over to the server: 1*

---> Send 11 bytes - Marker packet timestamp=020-12-26 23:52:26.129

        One data byte.
        Hex character sent over to the server: 2

<--- Received 11 bytes - Marker packet  timestamp=020-12-26 23:52:26.131
        One data byte.
        Hex character sent over to the server: 2

<--- Received 10 bytes - Data packet  timestamp=020-12-26 23:52:26.134
        Data Packet flags:
                End of file

Please notice that the sample_time when I made V$SESSION snapshot is 23:52:25.741. The time corresponds to this generic authentication call (OAUTH) line.
The 'Failed Logon Delay' is self-explanatory as well. Provided you have some auditing in place, it is more likely you will see some transaction calls you mentioned.
I cannot reproduce it with valid connections at the moment, but I guess it can happen too.

On Sat, 26 Dec 2020 at 21:50, Radoulov, Dimitre <cichomitiko_at_gmail.com> wrote:

> Hello all,
>
> I noticed that some records in the active session history views report
> user_id = 0 (sys) and machine indicating remote clients which I'm sure
> are not using sys user to connect to the database. In my case the
> TOP_LEVEL_CALL_NAMEs are LOGOFF, OAUTH, VERSION2, ROLLBACK, Transaction
> Commit/Rollback.
>
> I suppose these are some internal clean up operations, but I don't
> understand why some of them are associated with remote clients and
> others with the database server.
>
> Does anybody know why this might be happening?
>
> Thanks!
>
> Regards
> Dimitre
>
> --
> http://www.freelists.org/webpage/oracle-l
>
>
>

--
http://www.freelists.org/webpage/oracle-l
Received on Sun Dec 27 2020 - 01:17:30 CET

Original text of this message