Mining Information From The Listener Log By Arun Nanda

Mining Information from the Listener Log By Arup Nanda An Oracle database infrastructure has several components — the database, the listener, and the clustering components (CRS, CSS, ONS, and so on, if it’s a RAC database). All these components produce extensive logs to let you know what’s happening behind the scenes. These logs show information vital to understanding the working of the database. Perhaps the most popular and most commonly used is the database alert log, which offers a running commentary on the operation of the database. You may find many utilities and tools, including the Grid Control and Database Console interfaces from Oracle itself, to parse the alert log and reveal valuable information. However, a very useful source of information is often overlooked — the listener log. The listener log shows some information that is not available anywhere else (for example, the service names used by the clients). Some of the information can also be obtained by other means, such as via the IP address of the clients recorded in audit trails. But even in such cases, the listener log provides a non-intrusive source for which you don’t have to place instrumentation inside the database, as you must do when turning on auditing. In addition, listener logs also record the listener operations, both successful and unsuccessful, which can show attacks against the listener. Since listener is usually the target of many database attacks, this information can reveal valuable clues and help you build better defenses. In summary, listener logs provide far too much valuable information to be ignored. In this article, you will learn how to build an infrastructure to process the listener log and to use it to unearth information on your database operations. The information can be used in different scenarios, as you will see later.

Standard Disclaimer o

o

This article is based on my independent research into the composition of the listener log, and not from extracts from any other source, including Oracle manuals. While I have made every attempt to derive and present accurate information, there is no guarantee that the format of listener log will not be changed in some Oracle version, or will not have been changed already for some platforms. Therefore, I’m not making any kind of statement guaranteeing the accuracy of the findings on this paper. The results and output are from an actual production database infrastructure, but the identifying information such as IP Address, Host Name, usernames, and so on, have been masked to hide their identities. If it resembles any actual infrastructure, it is purely coincidental.

Building the Interface The listener log file is a simple text file, so searching for specific information inside is easy; however, in its raw form, it’s difficult to extract collated information. To make it easier, you must first build an interface to search and extract information in any manner you want. The best way to do that is a widely used, and powerful, interface, the humble SQL*Plus and the powerful language SQL. But how could you use the SQL language to extract and summarize the information from the listener log? Simple — by using an external table; by presenting the listener log as an external table, you can easily create powerful SQL statements to extract useful pieces of information.

Full listener log

Let’s get down to business. First, let’s create a table from the listener log, with one record per line in the log. Before you do that, you must create a directory object on the location of the listener log: create directory LISTENER_LOG_DIR as '/u01/app/oracle/10.1/db1/network/log' / Of course, you should change the location of the listener log file to whatever your system uses. If you are not sure, you can find find this information by using the listener control utility: prolin01.oraprol:/u01/app/oracle/dbaland/tools # lsnrctl status listener_prolin01 LSNRCTL for HPUX: Version 10.1.0.4.0 - Production on 11-NOV-2005 20:24:37 Copyright (c) 1991, 2004, Oracle.

All rights reserved.

Connecting to (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=proprd1.proligence.com)(PORT=1521) (IP =FIRST))) STATUS of the LISTENER -----------------------Alias LISTENER_PROLIN01 Version TNSLSNR for HPUX: Version 10.1.0.4.0 - Production Start Date 10-NOV-2005 22:34:10 Uptime 0 days 21 hr. 50 min. 26 sec Trace Level off Security ON: Local OS Authentication SNMP OFF Listener Parameter File /u01/app/oracle/10.1/db1/network/admin/listener.ora Listener Log File /u01/app/oracle/10.1/db1/network/log/listener_prolin01.log Note the line that shows “Listener Log File,” which shows the directory of the listener log file. Now, you are ready to build the external table on the listener log, using the following script: create table full_listener_log ( line varchar2(4000) ) organization external ( type oracle_loader default directory LISTENER_LOG_DIR access parameters ( records delimited by newline nobadfile nologfile nodiscardfile )

location ('listener_prolin01.log') ) reject limit unlimited / Replace the log file name mentioned in the location parameter with whatever is the name of the real log file. Once this is done, you can select data from this external table using simple SQL. The following is a partial output from the file without any filtering: SQL> select * from full_listener_log; LINE ------------------------------------------------------------------------------Trace level is currently 0 Started with pid=18597 Listening on: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=10.20.188.29)(PORT=1521) )) Listening on: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=10.20.188.28)(PORT=1521) )) TIMESTAMP * CONNECT DATA [* PROTOCOL INFO] * EVENT [* SID] * RETURN CODE 16-OCT-2005 04:58:06 * (CONNECT_DATA=(SID=proprd1)(CID=(PROGRAM=)(HOST=__jdbc__) (USER=))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.20.191.93)(PORT=43829)) * establish * proprd1 * 12505 TNS-12505: TNS:listener does not currently know of SID given in connect descript or 16-OCT-2005 04:58:06 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=prolin01)(USER=oraprol ))(COMMAND=status)(ARGUMENTS=64)(SERVICE=LISTENER_PROLIN01)(VERSION=16882176 0)) * status * 0 You can now use this to find specific pieces of information. For instance, you can find out the log files the listener produces by searching the lines that start with a pattern: SQL> select * from full_listener_log 2 where line like 'Log messages written%' 3 / The output (partial) is: LINE ------------------------------------------------------------------------------Log messages written to /u01/app/oracle/10.1/db1/network/log/listener_prolin01.l

og Log messages written to /u01/app/oracle/10.1/db1/network/log/listener_prolin01.l og Log messages written to /u01/app/oracle/10.1/db1/network/log/listener_prolin01.l og Log messages written to /u01/app/oracle/10.1/db1/network/log/listener_prolin01.l og You can, of course, search for any string you want using this procedure. Typical search strings may be the IP addresses the listener uses to listen on, the errors it encounter, and so on.

Detailed table This external table shows the entire listener log, one record per line in the file. This is useful when you want to see the records without any kind of formatting. However, remember that the original intent was to extract useful information from the log; given this, the raw format is not very useful. You need to extract information from these logs in a decipherable format. So, let’s build another table that shows the contents of the log file by breaking the lines into individual fields. To do this this, you must first understand the structure of the listener log. Most of the lines in the listener log follow a format with the fields shown as follows:      

The date and timestamp of the log entry The connect string used by the client The protocol related information (TCP/IP, port, etc.) used by the client The action by the client, e.g. status, establish connection, etc. The service_name used in the client’s connect string The return code of the action. If the return code is 0, then the action was successful; otherwise the error code is shown.

The fields are separated from each other by “*” character. Note: Not all the log entries follow this format, although most of them do. Here are some examples of the log entries, when the listener comes up: TNSLSNR for HPUX: Version 10.1.0.2.0 - Production on 14-SEP-2005 20:20:51 Copyright (c) 1991, 2004, Oracle.

All rights reserved.

Log messages written to /proprd/oracle/products/10.1/db1/network/log/listener_o dssdb01.log Trace information written to /proprd/oracle/products/10.1/db1/network/trace/lis tener_prolin01.trc Trace level is currently 0

Started with pid=3134 These messages do not follow a pattern of many fields; all information is contained in just one line. For the summarized information, you may ignore them, since they don’t contain data of interest. If needed, these can be extracted from the table FULL_LISTENER_LOG. Some other messages follow a pattern, but some fields are missing. For example, when a database registers itself with the listener and updates its load information, the following line appears: 16-SEP-2005 01:22:58 * service_update * PROPRD1 * 0 In this example, there are only four fields — Timestamp, Action, Service Name, and Return Code. Even though there are only four fields, not six, you can still parse them, but be aware of the contents of each field. Another instance of a message being generated that is missing some fields occurs when the user issues a STATUS command from the LSNRCTL prompt. A line as shown below appears in the log: 16-SEP-2005 01:27:26 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=prolin01)(USER=oraods s))(COMMAND=status)(ARGUMENTS=64)(SERVICE=LISTENER_PROLIN01)(VERSION=1688217 60) ) * status * 0 This line also has only four fields — Timestamp, The Connect Data used by the client, the action, and the return code. However, the interpretation of the fields is different in this case; as long as you understand what information each field contains, you should be able to “slice and dice” the listener log any way you want. Most lines will follow the six-field approach, and those lines are the ones that contain the information you are seeking. Therefore, building a standard table is not that difficult. The following shows how to build the table: create table listener_log ( log_date date, connect_string varchar2(300), protocol_info varchar2(300), action varchar2(15), service_name varchar2(15), return_code number(10) ) organization external ( type oracle_loader default directory LISTENER_LOG_DIR access parameters ( records delimited by newline nobadfile nologfile nodiscardfile

fields terminated by "*" lrtrim missing field values are null ( log_date char(30) date_format date mask "DD-MON-YYYY HH24:MI:SS", connect_string, protocol_info, action, service_name, return_code ) ) location ('listener_prolin01.log') ) reject limit unlimited / Needless to say, you must change the name of the listener log file in the location parameter. When created, the structure of the table looks like this: LOG_DATE CONNECT_STRING PROTOCOL_INFO ACTION SERVICE_NAME RETURN_CODE

DATE VARCHAR2(300) VARCHAR2(300) VARCHAR2(15) VARCHAR2(15) NUMBER(10)

Voila! The table is ready to be mined for the valuable data it contains. Before you start, let’s exsplore how to interpret the fields.

Description of Fields Since you have now divided the lines to different parts, you can see what information they contain. The fields show information in nested groups enclosed by parentheses. The following is a partial extract from the field CONNECT_STRING: (CONNECT_DATA=(CID=(PROGRAM=)(HOST=prolin01 ....... Each of these fields may have subfields nested inside within a second pair of parentheses. For instance, in the line previously noted, the field CONNECT_DATA has a nested column — CID — which, in turn, has nested fields PROGRAM, CID, and so on. Let’s see how these fields are structured.

Connect String Connect String has the following components nested inside: 1. SID — the Oracle SID. This is populated only if the user connects using the SID; otherwise, it’s NULL. 2. CID — a further nested field. This has the following subfields:

a. PROGRAM — the name of the program issued by the client b. HOST — the host name from which it came. In some cases, the host name is now shown if the client is a JDBC clone program. c. USER — the Operating System UserID of the user that issued the command. 3. SERVER — Shows the type of the connection the client used - DEDICATED or SHARED 4. SERVICE_NAME — If the client used a service name, instead of SID, it comes here. 5. COMMAND — the actual command issued by the user, or issued by some other process. For instance, the user may have issued “status” to see the status, and pmon process may have issued “service_update” to update the listener with its load data. The COMMAND argument can be one of: services status stop service_register service_update service_died 6. SERVICE — this is only present when the listener control utility commands are given, e.g. STATUS, SERVICES, etc. It’s nested with the following elements: a. DESCRIPTION i. ADDRESS 1. PROTOCOL 2. HOST 3. PORT 7. FAILOVER_MODE — this is present only is the client used a failover enabled connect string to connect. It’s also a nested field. It has four sub-fields: a. TYPE — the type of the failover, e.g. BASIC b. METHOD — the method of failover, e.g. PRESELECT c. RETRIES — the number of retries the client makes d. DELAY — the delay between the connection attempts Not all of the fields are relevant in a listener log; for example, when the user does not use SID to connect, but uses SERVICE_NAME, the SID field is irrelevant. When a field is not relevant, the field itself could be completely absent or it could be null; in the case of (SID=), for instance, there is no value after the “=” sign. You have to understand how to interpret information in both scenarios.

Protocol Information The field Protocol Information has the following subfields: PROTOCOL — the protocol that the client has used to connect, such as TCP. HOST — the IP address of the client machine. PORT — the port number established by the listener. (Note: It’s not the port number to which the listener is listening, so this is not especially interesting to us.)

Enhancing the Interface

Now, you not only know that the fields CONNECT_STRING and PROTOCOL_INFO may have single values, but they may have strings containing sub-columns as well. It’s vital that you extract the values of these subcolumns as accurately as possible. This can be done by parsing the field to search for specific strings such as HOST and extracting the value after the “=” sign. What could be better than a function that does all f that? The following is a function that accepts both:  

The string that needs to searched for the parameter names The parameter name that needs to be searched inside the string passed above

That function has been shown as follows: 1 create or replace function parse_listener_log_line 2 ( 3 p_in varchar2, 4 p_param in varchar2 5 ) 6 return varchar2 7 as 8 l_begin number(3); 9 l_end number(3); 10 l_val varchar2(2000); 11 begin 12 if p_param not in ( 13 'SID', 14 'SERVICE_NAME', 15 'PROGRAM', 16 'SERVICE', 17 'HOST', 18 'USER', 19 'PROTOCOL', 20 'TYPE', 21 'METHOD', 22 'RETRIES', 23 'DELAY', 24 'PORT', 25 'COMMAND' 26 ) then 27 raise_application_error (-20001,'Invalid Parameter Value '||p_param); 28 end if; 29 l_begin := instr (upper(p_in), '('||p_param||'='); 30 l_begin := instr (upper(p_in), '=', l_begin); 31 l_end := instr (upper(p_in), ')', l_begin); 32 l_val := substr (p_in, l_begin+1, l_end - l_begin - 1); 33 return l_val; 34* end; Let’s see how this function works. Line# Description

3 The input string inside which you need to search 4 The string that needs for which you need to search 12-26 You define the valid values of strings that show up as a parameter inside the listener log; this limits mistakes that can made during the search 29-32 You search for the presence of this parameter, note the position of the parentheses and the equality sign, and determine the position of the value of the paramet Now that this function is complete, let’s see how it works. The following is a sample of the values in the column connect_string: CONNECT_STRING -------------------------------------------------------------------------------

(CONNECT_DATA=(SID=proprd1)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=))) (CONNECT_DATA=(CID=(PROGRAM=)(HOST=prolin01)(USER=oraprol))(COMMAND=status)( ARG UMENTS=64)(SERVICE=LISTENER_PROLIN01)(VERSION=168821760)) (CONNECT_DATA=(SID=proprd1)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=))) (CONNECT_DATA=(SID=proprd1)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=))) To see the value of the parameter USER in the previous values, notice a few interesting things:  



The first few lines are null, probably because the lines couldn’t be parsed properly, and hence, were discarded. There is no mention of any parameters there, let alone USER. The first non-empty line has the parameter USER, but the string is (USER=), which indicates that the value of the parameter is NULL. The same is true for some following lines as well. The second line has the value of USER as oraprol from the string (USER=oraprol).

So, if you parse the lines for the value of the parameter UER, what should happen? To show null values, you can use the “?” character. SQL> set null ? SQL> select parse_listener_log_line(connect_string,'USER') 2 from listener_log; PARSE_LISTENER_LOG_LINE(CONNEC ------------------------------------? ? ? ?

? ? oraprol ? ? Note that the value was extracted only when it was a valid value. The function safely parses the input string and reports a value only if it’s present. This function will be our tool to extract information from the listener log lines.

Get Down to Mining Now that you have a basic understanding of how you can interpret the listener log, let’s discuss some of the basic information you can extract, then focus on the more advanced commands.

Listener stop To find the entries that occurred when the listener was stopped, you can search for the parameter COMMAND inside the CONNECT_STRING, which should have been “stop.” This is a very important piece of information. If someone killed the listener process from the UNIX prompt instead of issuing a “lsnrctl stop” command, then the line showing (COMMAND=stop) will not appear in the log; this tool can help determine how many times, and when, the listener was gracefully stopped. col host format a20 col l_user format a20 col service format a15 col logdate format a20 select to_char(log_date,'mm/dd/yy hh24:mi:ss') logdate, parse_listener_log_line(connect_string,'HOST') host, parse_listener_log_line(connect_string,'USER') l_user, parse_listener_log_line(connect_string,'SERVICE') service from listener_log where parse_listener_log_line(connect_string, 'COMMAND') = 'stop'; Here is the output: LOGDATE -------------------10/16/05 05:35:41 10/27/05 21:04:50

HOST ---------------prolin01 prolin01

L_USER ----------------oraprol oraprol

SERVICE --------------LISTENER_PROLIN01 LISTENER_PROLIN01

There it is. From the output, you know that on 10/16/05 5:35:41 AM, the user “oraprol” issued a stop command to the listener named “LISTENER_PROLIN01” on the host prolin01.

Program usage The code noted previously is useful, but you are looking for more interesting information, something you can use to make your database operation better. One question that comes up frequently is, what kind of tools are people using to access the database. How can you find out?

The answer lies in the parameter PROGRAM in the listener log, under the field CONNECT_STRING. Here is a query that’s used to show what programs users are using: col program format a70 col cmt format 999,999 select parse_listener_log_line(connect_string,'PROGRAM') program, count(1) cnt from listener_log group by parse_listener_log_line(connect_string,'PROGRAM'); The output is shown as follows: C:\InstalledPrograms\Quest Software\TOAD\TOAD.exe C:\Oracle\product\10.1.0\Client_1\jdk\jre\bin\java.exe C:\Program Files\Actuate7\Server\operation\fctsrvr7.exe C:\Program Files\Embarcadero\DBA700\DBArt700.exe C:\Program Files\Informatica PowerCenter 7.1\Client\pmdesign.exe C:\Program Files\Microsoft Office\OFFICE11\EXCEL.EXE C:\Program Files\Microsoft Office\Office10\MSACCESS.EXE C:\Program Files\Oracle\jre\1.1.8\bin\jrew.exe C:\Program Files\PLSQL Developer\plsqldev.exe C:\Program Files\Quest Software\Quest Central\QuestCentral.exe C:\Program Files\Quest Software\TOAD\TOAD.exe C:\Program Files\Quest Software\Toad for Oracle\TOAD.exe C:\Programs\TOAD\TOAD.exe C:\opt\TOAD\TOAD.exe C:\opt\toad\toad.exe C:\oracle\ora10g\BIN\sqlplusw.exe C:\oracle\ora81\bin\sqlplus.exe C:\oracle\ora92\bin\sqlplusw.exe C:\oracle\product\10.1.0\Client_1\BIN\sqlplusw.exe C:\oracle\product\10.2.0\db\bin\sqlplus.exe F:\Programs\Quest Software\TOAD\TOAD.exe c:\9I_CLIENT\bin\sqlplus.exe exp@odsddb01 odbcad32.exe oracle oracle@stcdwhdd sqlplus

1 15 25,796 53 1 20 4 9 19 2 846 32 13 5 1 11 2 44 26 77 16 5 2 1 31 4 20 402,752

This shows a pretty interesting picture; let’s do some analysis. Most of the sessions (402,752 of them) include the column NULL, indicating that the users may have been using some other access mechanism. A large number of the sessions (25,796 of them) use the program “C:\Program Files\Actuate7\Server\operation\fctsrvr7.exe,” which seems to be Actuate, a reporting program. The number sounds unusually high since this is an OLTP database, but then again, this may be justified. Either way, knowing this information keeps you better informed. Note the following lines: C:\Program Files\Quest Software\TOAD\TOAD.exe C:\Program Files\Quest Software\Toad for Oracle\TOAD.exe

846 32

C:\Programs\TOAD\TOAD.exe C:\opt\TOAD\TOAD.exe C:\opt\toad\toad.exe

13 5 1

The previous example shows various TOAD applications being used. You can use this to track TOAD users (and any issues associated with these users), and later, you’ll know how to see the host names and IP addresses from their point of origination: Note the following lines: C:\Program Files\Microsoft Office\OFFICE11\EXCEL.EXE C:\Program Files\Microsoft Office\Office10\MSACCESS.EXE

20 4

The first two lines show that someone accessed the database using Microsoft Excel and Microsoft Access, perhaps using ODBC drivers. Do you want to allow such a practice? That’s your call, but you are better prepared to answer this if you are well informed. Finally, note the following line: C:\Program Files\PLSQL Developer\plsqldev.exe

19

This shows some program named “plsqldev.exe,” which has made 19 connections. This is not exactly familiar software. It may be interesting to track this user down and ask about the software. Similarly, the log may show a number of other interesting facts about the types of programs users are using to access the database.

Conclusion In this article, I showed you how to build this powerful tool and just two examples in which I used the tool to enhance my knowledge of the database system and how it is used by others. I provided these two examples to show the power of this tool; they are, by no means, the defining boundaries. In part two of this series, I will show you how to use this tool to solve more complex and real-life issues that require deeper mining. In part one of this article, I showed you how to build a tool to mine information from a valuable, yet often overlooked, source of database activity — the listener log file. You also saw two basic examples of instances in which the tool was used. In this second part of the article series, I will show you how to use the tool in a more advanced manner. (If you haven’t read part 1 yet, please read it before continuing; how to build the tool has been described there.)

Standard Disclaimer 

This paper is solely based on my independent research into the composition of the listener log and not an extract from any other source, including Oracle manuals. While I have made every attempt to derive and present accurate information, there is no guarantee of its accuracy if the format of listener log will be changed in some Oracle version, or has not been changed already for some platforms. Therefore, I’m not making any kind of statement guaranteeing the accuracy of the findings on this paper.



The results and output are from an actual production database infrastructure; however, the identifying information, such as IP Address, Host Name, usernames,and so on, have been masked to hide their identities. If it resembles any actual infrastructure, it is purely coincidental.

Service Name Usage If you have a RAC database, you may have introduced a few features to support some of the advanced functionalities of RAC, e.g., load balancing across nodes and making sessions fail over to a surviving node when a node dies. These things will occur only if users are employing the proper connect string, utilizing SERVICE_NAME and not SID. Here is one way to use connect strings, utilizing service name PROMEET connecting to the RAC database running on three nodes – prolin1, prolin2 and prolin3. PROPRD = (DESCRIPTION = (LOAD_BALANCE = on) (FAILOVER = on) (enable = broken) (ADDRESS = (PROTOCOL = TCP)(HOST = prolin1)(PORT = 1521)) (ADDRESS = (PROTOCOL = TCP)(HOST = prolin2)(PORT = 1521)) (ADDRESS = (PROTOCOL = TCP)(HOST = prolin3)(PORT = 1521)) (CONNECT_DATA = (SERVER = DEDICATED) (SERVICE_NAME = PROMEET) (FAILOVER_MODE = (TYPE = SELECT) (METHOD = BASIC) (RETRIES = 120) (DELAY = 2) ) ) ) An example of the connect string using SID is shown as follows: PROPRD = (DESCRIPTION = (ADDRESS = (PROTOCOL = TCP)(HOST = prolin1)(PORT = 1521)) (CONNECT_DATA = (SID = PROPRD1) ) ) In this case, if the node prolin1 fails, the session will not fail over to the other surviving node. If the client attempts to make the connection again, it will fail, and users should understand this. How can you proactively capture these users, still utilizing the SID? You can’t get that information from the dynamic performance view V$SESSION; the listener log records that data.

When the users employ a connect string using the SID, the listener log entry shows SID as a nested parameter in the field CONNECT_STRING. If they use SERVICE_NAME, the SID is not present or NULL. You can then parse the field for the parameter and check the value. col sid format a15 select parse_listener_log_line(connect_string,'SID') sid, count(1) cnt from listener_log group by parse_listener_log_line(connect_string,'SID'); The output is: SID CNT --------------- ---------PROPRD 1 PROPRD1 16292 PROPRD2 1 PROSRCH 1 proprd1 64601 proprd2 3242 349780 This produces some interesting results. We see that 349,780 of them (where the SID value is NULL) have used SERVICE_NAME, but not the others. A total of 64,601 sessions used proprd1 as the SID, and 16,292 used PROPRD1 as the SID name. It will be a good idea to go after those users and inquire why they are not using the SERVICE_NAME. Regardless of the reason, you can make them aware that their sessions will not fail over in case of failure in the instance to which they are connected. Besides RAC failover, Service Names are also used in a variety of other ways, such as to control resource usage through Resource Manager, to track SQL performance, and track database usages such as CPU and IO. If you are planning to enforce Service Name adoption in your database, this is a great way to start, and later it will be a tool to track the progress of its adoption. There is an interesting fact in the output here. Note the line: PROSRCH

1

There is no SID named PROSRCH for which this listener is paying attention. So, how come this listener appears in the above output? The presence in the listener log indicates that the user has tried to connect; but may not have been successful. Let’s confirm that: SQL> 2 3 4

select return_code from listener_log where parse_listener_log_line(connect_string,'SID') = 'PROSRCH' /

RETURN_CODE ----------12505

The return code is 12505. The client must have received the error TNS-12505 while making this connection attempt. To see what the error means, you can use the “oerr” utility: prolin01.oraprol:/u01/app/oracle/10.1/db1/network/log # oerr tns 12505 12505, 00000, "TNS:listener does not currently know of SID given in connect descriptor" // *Cause: The listener received a request to establish a connection to a // database or other service. The connect descriptor received by the listener // specified a SID for an instance (usually a database instance) that either // has not yet dynamically registered with the listener or has not been // statically configured for the listener. This may be a temporary condition // such as after the listener has started, but before the database instance // has registered with the listener. // *Action: // - Wait a moment and try to connect a second time. // - Check which instances are currently known by the listener by executing: // lsnrctl services <listener name> // - Check that the SID parameter in the connect descriptor specifies // an instance known by the listener. // - Check for an event in the listener.log file. The mystery is clear now. This connection was accepted by the listener; but then the listener immediately refused the connection with a TNS-12505 error since there was no SID named PROSRCH to which it was listening. Now let’s be a little more helpful. Why did this user connect using an invalid SID? There are many possible explanations — one of them being that, perhaps, we told them to use that SID? No, that’s not possible; we know the SID well enough to tell it correctly. A more likely reason could be that we told them PROSRCH was the service name to use, but they misunderstood and thought it was the SID. Now, the connection didn’t work, and we may have a disgruntled and confused user. Let’s put on our “good neighbor hat” and proactively seek this user out to correct the mistake. The best way to do so is by selecting all the columns of the table for that record: SQL> 2 3 4

select return_code from listener_log where parse_listener_log_line(connect_string,'SID') = 'PROSRCH' /

The output is shown below in a vertical format to make the values more readable. LOG_DATE : 18-oct-2005 11:30:28 CONNECT_STRING : (CONNECT_DATA=(SID=PROSRCH)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=))) PROTOCOL_INFO : (ADDRESS=(PROTOCOL=tcp)(HOST=10.14.105.105)(PORT=3164)) ACTION : establish SERVICE_NAME : PROSRCH RETURN_CODE : 12505

The output shows that the user connected from the IP address 10.14.105.105, using TCP connection. The HOST value shows __jdbc__, which typically indicates a JDBC thin client. We can find out which application group owns this appserver and tell them about the error. We can feel the tinkle in their eye when we tell them, “hey Joe, on October 18th, at 11:30 AM, your appserver 10.14.105.105 tried to connect to the database but failed with a TNS-12505 error; and we know exactly why”. Won’t we look like heroes?

Do We Have Too Many Service Names You have diligently defined several service names inside the database, which makes it easier to track individual groups of users. However, even after defining all the services, there is no guarantee that the users have selected these service names. How can you ensure they have been using these service names? Have you defined service names that are not being used? Checking the SERVICE_NAME column from the dynamic view V$SESSION does not work because the row shows a session occuring at the current time only; once the user disconnects, the session disappears. But just because you don’t see a service name being used does not mean that it has not been used. It may have been used before. So, how can you be sure which service names have never been used? Again, the listener log comes to rescue. To find this information, use the following query: select name from v$services minus select distinct parse_listener_log_line(connect_string,'SERVICE_NAME') from listener_log / The output shows the following: NAME ----------------------AFCP DJ SARATOGA PVO SYS$BACKGROUND SYS$USERS PROCOMM PROMEET This is pretty enlightening. Note, the service names SYS$BACKGROUND and SYS$USERS are not defined by the user; they are default service names. So it is easy to understand why they would show up. What about the others? To find the answer, we will need to check the service names used by clients from the listener log: SQL> select distinct parse_listener_log_line(connect_string,'SERVICE_NAME') 2 from listener_log 3 / PARSE_LISTENER_LOG_LINE(CONNEC -----------------------------------------------------------------------------ADHOC

PNAT BOOKING DBA DWETL PROPEDIA PCAT PROCOMM PROMEET PROPRD PROPRD_ADHOC OMT PROLO REPORT PROMSG RESPONSE PROSVC PROSRCH SLC adhoc dba dj proprd proprd1 omt response service_name PROSVC slc Again, this shows some interesting results. The service names DJ, PROMEET, and PROCOMM have been used earlier. They showed up in the “not used” list, but note carefully – they showed up as “dj,” “PROMEET,” and “PROCOMM,” all in lowercase, not uppercase. So there are two service names defined in the database — “PROCOMM” (uppercase) and “PROCOMM” (lowercase). The same is true for PROMEET and DJ. But the other service names — AFCP, SARATOGA and PVO — have never been used. This is the only way to know that whether or not a service has been used. Of course, you can always check from AWR; but if AWR has been disabled, for whatever reason, that source is gone also. In any case, the method I’ve just shown is the easiest way to find out.

Tracking Client Machines While building a security perimeter around your database, the most important thing to find out is how to track the hot machines from which the users are connect. How can you find out? Of course, one option is to turn on auditing and then track the client hosts. However, that may not be possible for a variety of reasons — auditing is an intrusive activity; the audit trails are written to system tablespace and may cause database failure if they make the tablespace fill up. To get an audit trail, the database must be restarted after setting the parameter audit_db to DB in the database initialization parameter file; however, that may not be feasible, and so on. We don’t need to do all that; we can turn to our new friend the listener log for that information. To get this data, we can look into the value of the parameter HOST in the field CONNECT_STRING:

col host format a40 select parse_listener_log_line(connect_string,'HOST') host, count(1) cnt from listener_log group by parse_listener_log_line(connect_string,'HOST'); The output is: HOST CNT ---------------------------------------- ---------BRAACTPAS02 1 BRAACTPAS03 26013 GYEET30 34 IBM-CGAGNE-T30 2 ST-ACHAN-T40 9 ST-LKWANG-T41 18 ST-NDRACEA-T40 30 STACHISHOLT42 20 STADHIMANT41 1 STAFOSTERT42 12 STANANDAT42 81 STATHOTANG 41 STATRANT41 18 STBJONEST41 1 STBQUINT41 13 STBWALSHT41 37 STCABUTTARO03 55 STCARINTOUL04 28 STCDCANNON02 15 STCDGILLIS01 6 STCGGU01 11 STCGLIGHT02 51 STCGMINYARD01 15 STCGWRINN02 1 STCHJALILI02 54 STCJHARDIN02 1 STCJSIWEK02 13 STCKBASEY01 2 STCKENLUB01 55 STCKESSEGIAN03 1 STCMSTDIS01 1 STCNGT40 5 STCNORTONT41 11 STCPARKT41 5 STCPKETELTAS03 2 STCROSSEDM01 6 STCSPRASAD02 9 STCWALKERT30 2 STCYHERWONO01 2 STCYKOSTOVA02 4 STDDELRIOT40 24 STDFANELLIT41 13

STEDEANT41 STHZEIGLERT41 STHZIEGLER40 STJARCHERT41 STJEILERST40 STJJENKINST41 STJNELSONT40 STJSABOTKAT40 STKFORNERT30 STMJAMEST41 STMLEET41 STNHEBBART41 STNRAZAKT41 STR-NROYCROF-T4 STR-ODADA-T40 STR-PJAIN-T41 STR-QCHAO-T40 STRKGOVINDAT30 STRMROYCROFTT3 STRSCOTIGERT3 STSPATELT40 STSZHANGT40 STTNGT40 STSCOTIGERAT42 STUMSTEARMAT41 STVCHANGT41 STWCHOIT41 SW0001022C042B __jdbc__ localhost.localdomain odsddb01 prolin01 prolin02 odsqdb02 sgpas02 stcbkgpas01.proligence.com stcdocpdb01 stcdwhdd stcdwhpd stcdwhqd stcfogpdb01.starwoodhotels.com stciispas01 stcshrpas06 stcudtpdb03

83 23 1 41 77 25 13 5 35 12 18 3 20 19 6 4 3 3 3 3 16 8 11 1 25 8 17 16 337824 13 2 29793 2 2 35 2 4841 10 14831 10 20 2329 4418 6 12632

This output should be a great help in understanding which client machines are connect to the database, and for how long. While going through this list, it’s important to note well known appservers; most of the connections should be coming from them. If not, then you may have a rogue client banging away at the database without your knowledge. In any case, it’s good to keep a history of these connections and compare them from time to time, because this will reveal when the new clients come on to connect to the database.

Note the following line: __jdbc__

337824

It indicates that the host named __jdbc__ has tried to connect 337,824 times, but that doesn’t sound like a host name; so what is it? It indicates a JDBC thin driver, and that these connections came from an appserver connecting via a JDBC thin driver. So, how do you track these clients? The answer lies in the other column of our table — PROTOCOL_INFO — which also has a parameter called HOST. This parameter reflects the true IP address of the client. We can look for IP addresses from this column instead of the CONNECT_STRING: select parse_listener_log_line(protocol_info,'HOST') host, count(1) cnt from listener_log where parse_listener_log_line(connect_string,'HOST') = '__jdbc__' group by parse_listener_log_line(protocol_info,'HOST') order by count(1) The output is: HOST CNT ------------------------- ---------10.20.199.60 1 10.14.105.105 2 10.23.35.217 2 10.23.35.6 2 10.14.32.67 3 10.23.35.169 3 10.23.35.37 4 10.20.191.63 5 10.14.32.97 6 10.20.199.67 6 10.14.105.48 7 10.20.195.20 8 10.14.104.203 9 10.23.35.233 9 10.14.32.76 9 10.20.191.87 9 10.20.191.86 10 10.14.32.22 16 10.14.32.8 18 10.20.191.209 20 10.14.104.105 24 10.14.105.175 36 10.14.104.122 39 10.14.104.251 43

10.14.32.34 10.14.105.19 10.14.104.99 10.20.191.62 10.14.104.58 10.20.191.77 10.20.191.117 10.20.191.48 10.20.170.35 10.20.194.57 10.20.191.89 10.20.191.60 10.20.218.194 10.20.218.193 10.20.191.90 10.20.191.116 10.20.210.21 10.20.191.78 10.14.105.101 10.20.191.91 10.20.191.88 10.20.191.80 10.20.210.23 10.20.191.82 10.20.191.76 10.20.191.125 10.20.191.93 10.20.214.170

66 80 81 115 152 192 224 265 321 409 548 562 569 575 627 1174 1336 1594 1595 1804 1932 2358 2949 3682 4917 7207 48802 363442

Note these IP addresses and the number of connections they have made to the database. The last one — 10.20.214.170 — has made the largest number of connections. Is this your main application server? Going through the list should provide you with clues to identify a rogue appserver that is trying to establish connections.

Tracking Service Names Earlier, we saw how service names, rather than SIDs in connect string — whether in the JDBC connect string or in TNSNAMES.ORA file — help you immensely. They allow the sessions to fail over in a RAC environment; they help the DBA track the performance based on service name; they allow the DBA to allocate resource limits, and so on. Now that you have created all the service names and instructed everyone to use them, how can you make sure that users are actually using them? Simple; just mine some more jewels from our trusted friend, the listener log. When users connect to the database using SERVICE_NAME in the TNS connect string, the fact is recorded in the listener log, in the CONNECT_STRING field. The parameter is SERVICE_NAME. While searching for this parameter, you can also search for the HOST parameter; so that you can track which hosts are using Service Names and which ones are not. We will use the following query: col sn format a15 col host format a45 col cnt format 999,999

select parse_listener_log_line(connect_string,'SERVICE_NAME') SN, parse_listener_log_line(connect_string,'HOST') host, count(1) cnt from listener_log group by parse_listener_log_line(connect_string,'SERVICE_NAME'), parse_listener_log_line(connect_string,'HOST') The output is: SN HOST CNT --------------- --------------------------------------------- -------13,006 __jdbc__ 61,793 odsddb01 2 prolin01 30,553 odsqdb02 2 STMLEET41 18 STANANDAT42 53 STCKENLUB01 55 STNRAZAKT41 17 stcdocpdb01 4,907 ST-ACHAN-T40 9 STCROSSEDM01 6 STDDELRIOT40 18 STKFORNERT30 35 STCABUTTARO03 55 STCGMINYARD01 1 STCYHERWONO01 2 STCYKOSTOVA02 4 STJJENKINST41 25 ST-NDRACEA-T40 22 STCKESSEGIAN03 1 STCPKETELTAS03 2 STR-NROYCROF-T4 19 stcfogpdb01.starwoodhotels.com 21 dj stciispas01 2,365 dj IBM-CGAGNE-T30 2 DBA STATHOTANG 15 DBA STANANDAT42 31 DBA STCJSIWEK02 12 DBA STNRAZAKT41 3 DBA STSZHANGT40 8 DBA stcudtpdb03 6 DBA STRKGOVINDAT30 3 DBA STSCOTIGERAT42 1 DBA STUMSTEARMAT41 25 OMT __jdbc__ 156 OMT stcshrpas06 3,448 SLC __jdbc__ 260,819

SLC SLC dba omt slc PNAT PNAT PNAT PCAT PCAT PCAT PCAT ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC ADHOC DWETL DWETL DWETL DWETL DWETL PROLO adhoc adhoc adhoc

STVCHANGT41 STDDELRIOT40 STWCHOIT41 __jdbc__ STCGWRINN02 __jdbc__ STHZIEGLER40 ST-NDRACEA-T40 sgpas02 STTNGT40 __jdbc__ stcshrpas06 GYEET30 STCGGU01 STCNGT40 __jdbc__ prolin01 prolin02 STATRANT41 STBQUINT41 STCPARKT41 STEDEANT41 STCGLIGHT02 STCJSIWEK02 stcshrpas06 STAFOSTERT42 STCDCANNON02 STCDGILLIS01 STCHJALILI02 STCJHARDIN02 STCNORTONT41 STCSPRASAD02 STJARCHERT41 ST-LKWANG-T41 STBWEVODAUT42 STCARINTOUL04 STCGMINYARD01 STHZEIGLERT41 STR-PJAIN-T41 STRSCOTIGERT3 ST-NDRACEA-T40 localhost.localdomain prolin01 stcdwhdd stcdwhpd stcdwhqd STCMSTDIS01 __jdbc__ __jdbc__ STBWALSHT41 STRMROYCROFTT3

9 6 17 1 1 1,273 1 4 35 11 897 125 34 11 5 328 33 2 18 13 5 83 51 1 984 12 15 6 54 1 11 9 41 18 1 28 14 23 4 3 3 13 21 10 15,332 10 1 331 329 37 3

PROPRD REPORT PROMSG PROSVC PROSVC PROSVC PROSVC PROSVC PROSVC PROSVC PROSVC proprd proprd proprd PROSVC BOOKING PROPEDIA PROCOMM PROCOMM PROCOMM PROCOMM PROSRCH PROSRCH PROSRCH PROSRCH PROSRCH PROSRCH proprd1 PROMEET PROMEET PROMEET PROMEET RESPONSE response PROPRD_ADHOC service_name service_name

stcdocpdb01 BRAACTPAS03 __jdbc__ __jdbc__ BRAACTPAS02 BRAACTPAS03 STBJONEST41 STCKBASEY01 STCWALKERT30 STR-QCHAO-T40 SW0001022C042B __jdbc__ STATHOTANG stcdocpdb01 __jdbc__ __jdbc__ __jdbc__ __jdbc__ STMJAMEST41 STJNELSONT40 STDFANELLIT41 __jdbc__ STSPATELT40 STJEILERST40 STJSABOTKAT40 STR-ODADA-T40 stcbkgpas01.proligence.com __jdbc__ __jdbc__ STADHIMANT41 STNHEBBART41 STACHISHOLT42 __jdbc__ __jdbc__ __jdbc__ STDFANELLIT41 ST-NDRACEA-T40

217 27,071 3,275 2,910 1 29 1 2 2 3 17 128 26 1 6 2,195 8 2,288 12 13 12 7,538 16 79 5 6 2 9 976 1 3 20 181 475 1 1 1

The data previously shown reveals some very interesting information. Many sessions (shown towards the top of the output with the SN field as NULL) do not use Service Name. Now is the time to target them for a service name transition. Second, note the following lines: proprd proprd proprd

__jdbc__ STATHOTANG stcdocpdb01

128 26 1

Even though the service name column is not NULL, it shows the service name as proprd, the default service name; this means that the users connected as SID, or used the default service name, which should also be discouraged.

Third, note the following lines: PROPRD_ADHOC service_name service_name

__jdbc__ STDFANELLIT41 ST-NDRACEA-T40

1 1 1

This shows service names used by clients as PROPRD_ADHOC and service_name. These are not valid service names defined within the database. How could the user utilize them? Let’s take a closer look: select * from listener_log where parse_listener_log_line(connect_string,'SERVICE_NAME') in ('PROPRD_ADHOC', 'service_name') / The output is: LOG_DATE --------CONNECT_STRING -----------------------------------------------------------------------------PROTOCOL_INFO -----------------------------------------------------------------------------ACTION SERVICE_NAME RETURN_CODE --------------- --------------- ----------18-OCT-05 (CONNECT_DATA=(CID=(PROGRAM=)(HOST=__jdbc__)(USER=))(SERVICE_NAME=PROPRD_ADH OC) ) (ADDRESS=(PROTOCOL=tcp)(HOST=10.14.105.175)(PORT=3025)) establish PROPRD_ADHOC 12514 24-OCT-05 (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=service_name)(FAILOVER_MODE=(T YPE = SELECT)(METHOD=BASIC)(RETRIES=120)(DELAY=2))(CID=(PROGRAM=C:\Program Files\Quest Software\Toad for Oracle\TOAD.exe)(HOST=STDFANELLIT41)(USER=dfanelli))) (ADDRESS=(PROTOCOL=tcp)(HOST=10.14.105.101)(PORT=2721)) establish service_name 12514 27-OCT-05 (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=service_name)(FAILOVER_MODE=(T YPE = SELECT)(METHOD=BASIC)(RETRIES=120)(DELAY=2))(CID=(PROGRAM=C:\Program Files\Embar cadero\DBA700\DBArt700.exe)(HOST=ST-NDRACEA-T40)(USER=ndracea)))

(ADDRESS=(PROTOCOL=tcp)(HOST=10.14.104.113)(PORT=3948)) establish service_name 12514 Note the RETURN_CODE column, which is not zero in all cases. This indicates the connection attempt was not successful. Noting the hostnames and users, we can ask the users if they are having issues connecting to the database. If they continue to have issues, we can tell them exactly why, and again, we look like heroes. (Yeah, right!) Finally, note the following lines: DBA DBA DBA DBA DBA DBA DBA DBA DBA

STATHOTANG STANANDAT42 STCJSIWEK02 STNRAZAKT41 STSZHANGT40 stcudtpdb03 STRKGOVINDAT30 STSCOTIGERAT42 STUMSTEARMAT41

15 31 12 3 8 6 3 1 25

This output shows the hostnames connecting to the service name DBA. You may have allowed this special service name much higher resource utilization in the Resource Manager. So, if people start using this service name, you may have an issue. Going through the output, you could PROLOnize all the hostnames as the laptops of DBAs, except one — STSCOTIGERAT42, which belongs to a non-DBA. Why is that user connecting as DBA? Let’s take a closer look: select * from listener_log where parse_listener_log_line(connect_string,'SERVICE_NAME') = 'DBA' and parse_listener_log_line(connect_string,'HOST') = 'STSCOTIGERAT42' The output is: LOG_DATE --------CONNECT_STRING -----------------------------------------------------------------------------PROTOCOL_INFO -----------------------------------------------------------------------------ACTION SERVICE_NAME RETURN_CODE --------------- --------------- ----------02-NOV-05 (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=DBA)(FAILOVER_MODE=(TYPE=SELEC T)( M

ETHOD=BASIC)(RETRIES=120)(DELAY=2))(CID=(PROGRAM=C:\Program Files\Quest Software \TOAD\TOAD.exe)(HOST=STSCOTIGERAT42)(USER=SCOTIGER))) (ADDRESS=(PROTOCOL=tcp)(HOST=10.14.104.72)(PORT=1365)) establish DBA 0 The OS user that connected to the database was “SCOTIGERA,” who connected through TOAD. She did connect successfully, as shown by the value of the RETURN_CODE – zero. Looks like she only connected once on November 2. How else has she been connecting? select * from listener_log where parse_listener_log_line(connect_string,'HOST') = 'STSCOTIGERAT42'; The output is still the same record. So, she has only connected once to production, using the service name DBA. Now it’s a time to pay her a visit and point out to her that she should change her service name to a different one.

DBA Service Names Now that you have found that people have been using the service name DBA even though they are not DBAs, you are sure to be tempted to find out who else may be using it. Well, let’s ask the tool: col l_user format a15 col l_host format a30 col cnt format 999,999 select parse_listener_log_line(connect_string,'USER') l_user, decode ( parse_listener_log_line(connect_string,'HOST'), '__jdbc__', parse_listener_log_line(protocol_info,'HOST'), parse_listener_log_line(connect_string,'HOST') ) l_host, count(1) cnt from listener_log2 where parse_listener_log_line(connect_string,'SERVICE_NAME') = 'DBA' group by parse_listener_log_line(connect_string,'USER'), decode ( parse_listener_log_line(connect_string,'HOST'), '__jdbc__', parse_listener_log_line(protocol_info,'HOST'), parse_listener_log_line(connect_string,'HOST') ) order by 1,2,3 The previous DECODE statement was necessary since the HOST parameter in CONNECT_STRING does not contain the hostname in case of thin JDBC drivers; it contains the string “__jdbc__”. In this case, we should look into the HOST parameter inside the PROTOCOL_INFO, which will show the IP address of the client.

The output is as follows: L_USER --------------achakrap ananda athotang athotang julisiw kgovinda mstearma oracle oraprol SCOTIGER

L_HOST CNT ------------------------------ -------STSZHANGT40 6 STANANDAT42 30 STATHOTANG 16 stcudtpdb03 2 STCJSIWEK02 6 STRKGOVINDAT30 4 STUMSTEARMAT41 20 stcudtpdb03 1 prolin01 2 STSCOTIGERAT42 1

From the output, we see all the users and hostnames connecting as DBA service name. We can account for all, except the user “SCOTIGER,” who is not a known DBA. We have identified that in an earlier step, so it’s not a big issue. This output just confirmed that she was the only one; there has not been a rampant abuse of the DBA service name.

Conclusion In part 2 of the article series, you learned how to use this tool to reveal some more interesting and practical information — how Service Name is utilized by the users and from which machines the database connections are coming. With this information, you can steer users to employ a service name, and you can use it as a tracking tool, to monitor progress. The other information — the list of client machines — is very helpful when you are building a perimeter defense around the database servers, using a firewall or using connection manager to limit connections. In the third and concluding article of the series, you will learn how to extract even more constructive information and also how to use it for proactive security establishment. In the first two parts of this article series, you have learned how to build a tool to mine information from the listener log, which contains valuable information, yet is usually ignored in database analysis. If you haven’t already done so, please take a take a moment to go through part 1 and part 2 of this series. (Part 1 contains the description of this tool.) In this third, and last article of the series, you will see how to extract enhanced bits of information from the listener log and also how to tie it in with security analysis.

Standard Disclaimer 



This paper is solely based on my independent research into the composition of the listener log and not an extract from any other source, including Oracle manuals. While I have made every attempt to derive and present accurate information, there is no guarantee of its accuracy if the format of listener log will be changed in some Oracle version, or has not been changed already for some platforms. Therefore, I’m not making any kind of statement guaranteeing the accuracy of the findings on this paper. The results and output are from an actual production database infrastructure; however, the identifying information, such as IP Address, Host Name, usernames, and so on, have been masked to hide their identities. If it resembles any actual infrastructure, it is purely coincidental.

JDBC Connections Earlier, we saw that the HOST parameter in the CONNECT_STRING shows __jdbc__ when the client connects to the database using the JDBC thin driver. In this case, the real host name is shown in the HOST parameter in the PROTOCOL_INFO field. Using that knowledge, we can pull up a report on what service name is used from which client. The following query accomplishes this: select parse_listener_log_line(connect_string,'SERVICE_NAME') SN, parse_listener_log_line(protocol_info,'HOST') host, count(1) cnt from listener_log where parse_listener_log_line(connect_string,'HOST') = '__jdbc__' group by parse_listener_log_line(connect_string,'SERVICE_NAME'), parse_listener_log_line(protocol_info,'HOST'); The output is: SN HOST CNT --------------- --------------------------------------------- -------10.14.105.19 80 10.20.191.76 798 10.20.191.77 150 10.20.191.78 160 10.20.191.80 396 10.20.191.82 99 10.20.191.91 274 10.20.191.93 43,839 10.20.194.57 96 10.20.199.60 1 10.20.199.67 6 10.14.104.105 6 10.14.104.122 8 10.14.104.203 9 10.14.105.105 2 10.20.214.170 15,869 OMT 10.20.191.60 84 OMT 10.20.191.80 72 SLC 10.14.104.99 81 SLC 10.20.191.209 15 SLC 10.20.214.170 260,928 omt 10.20.191.60 1 PNAT 10.14.104.105 18 PNAT 10.20.191.116 1,056 PNAT 10.20.191.117 200 PCAT 10.20.191.60 325 PCAT 10.20.191.80 572 ADHOC 10.20.191.91 325

ADHOC PROLO PROLO PROLO PROLO adhoc adhoc adhoc adhoc PROMSG PROMSG PROMSG PROMSG PROMSG PROSVC PROSVC PROSVC PROSVC PROSVC PROSVC PROSVC proprd PROSVC PROSVC BOOKING BOOKING PROPEDIA PROCOMM PROCOMM PROCOMM PROSRCH PROSRCH PROSRCH PROSRCH PROSRCH PROSRCH PROSRCH PROSRCH PROSRCH PROSRCH proprd1 proprd1 PROMEET PROMEET PROMEET PROMEET RESPONSE RESPONSE response PROPRD_ADHOC

10.23.35.233 10.23.35.37 10.20.191.78 10.20.191.82 10.14.105.175 10.14.32.8 10.14.32.34 10.14.32.76 10.20.170.35 10.14.32.22 10.20.191.76 10.20.191.80 10.20.191.88 10.20.191.91 10.20.191.76 10.20.191.80 10.20.191.88 10.20.191.89 10.20.191.90 10.20.191.91 10.20.191.93 10.20.194.57 10.20.191.82 10.20.191.91 10.20.210.21 10.20.210.23 10.20.195.20 10.20.191.76 10.20.191.80 10.14.105.101 10.23.35.6 10.20.191.48 10.20.191.62 10.20.191.63 10.20.191.86 10.20.191.87 10.23.35.169 10.23.35.233 10.14.104.251 10.20.191.125 10.20.191.91 10.20.194.57 10.14.32.67 10.14.104.58 10.20.218.193 10.20.218.194 10.20.191.78 10.20.191.82 10.20.191.78 10.14.105.175

3 4 114 178 35 18 66 9 236 16 1,688 2 1,263 306 120 117 142 166 150 244 1,971 128 1 5 649 1,546 8 326 367 1,595 2 236 61 5 9 8 3 6 42 7,166 1 8 3 116 424 433 76 105 475 1

Now it’s time to match up client IP addresses to make sure they are correctly pointing to the right service name. Some client IP addresses use multiple service names since they run multiple applications. While there is no way to differentiate between applications, we can at least eliminate the possibility that an appserver uses a wrong service name.

SID or Service Name Breakup Now that you have seen how clients use both service names and SIDs while connecting, a consolidated report will help you to understand how clients connect, and will help us fix two potential issues — clients using SIDs instead of service names, and using wrong service names. We will use this information for JDBC thin clients only, because that’s where most of our applications are. You can use this query to see the breakup of the SID/Service Names: select parse_listener_log_line(connect_string,'SID') SID, parse_listener_log_line(connect_string,'SERVICE_NAME') SN, parse_listener_log_line(protocol_info,'HOST') host, count(1) cnt from listener_log where parse_listener_log_line(connect_string,'HOST') = '__jdbc__' group by parse_listener_log_line(connect_string,'SID'), parse_listener_log_line(connect_string,'SERVICE_NAME'), parse_listener_log_line(protocol_info,'HOST') The output is: SID SN ---------- --------------OMT OMT SLC SLC SLC omt PNAT PNAT PNAT PCAT PCAT ADHOC ADHOC PROLO PROLO PROLO PROLO adhoc adhoc

HOST CNT -------------------- -------10.20.191.60 84 10.20.191.80 72 10.14.104.99 81 10.20.191.209 15 10.20.214.170 261,029 10.20.191.60 1 10.14.104.105 18 10.20.191.116 1,056 10.20.191.117 200 10.20.191.60 325 10.20.191.80 572 10.20.191.91 325 10.23.35.233 3 10.23.35.37 4 10.20.191.78 114 10.20.191.82 178 10.14.105.175 35 10.14.32.8 18 10.14.32.34 66

adhoc adhoc PROMSG PROMSG PROMSG PROMSG PROMSG PROSVC PROSVC PROSVC PROSVC PROSVC PROSVC PROSVC proprd PROSVC PROSVC BOOKING BOOKING PROPEDIA PROCOMM PROCOMM PROCOMM PROSRCH PROSRCH PROSRCH PROSRCH PROSRCH PROSRCH PROSRCH PROSRCH PROSRCH PROSRCH proprd1 proprd1 PROMEET PROMEET PROMEET PROMEET RESPONSE RESPONSE response PROPRD_ADHOC PROPRD PROPRD1 PROPRD1 PROPRD1 PROPRD1 PROPRD1 PROSRCH proprd1

10.14.32.76 10.20.170.35 10.14.32.22 10.20.191.76 10.20.191.80 10.20.191.88 10.20.191.91 10.20.191.76 10.20.191.80 10.20.191.88 10.20.191.89 10.20.191.90 10.20.191.91 10.20.191.93 10.20.194.57 10.20.191.82 10.20.191.91 10.20.210.21 10.20.210.23 10.20.195.20 10.20.191.76 10.20.191.80 10.14.105.101 10.23.35.6 10.20.191.48 10.20.191.62 10.20.191.63 10.20.191.86 10.20.191.87 10.23.35.169 10.23.35.233 10.14.104.251 10.20.191.125 10.20.191.91 10.20.194.57 10.14.32.67 10.14.104.58 10.20.218.193 10.20.218.194 10.20.191.78 10.20.191.82 10.20.191.78 10.14.105.175 10.14.105.105 10.20.191.77 10.20.199.60 10.20.199.67 10.14.104.105 10.20.214.170 10.14.105.105 10.14.105.19

9 236 16 1,688 2 1,263 306 120 117 142 166 150 244 1,972 128 1 5 649 1,546 8 326 367 1,595 2 236 61 5 9 8 3 6 42 7,166 1 8 3 116 424 433 76 105 475 1 1 150 1 6 6 15,869 1 80

proprd1 proprd1 proprd1 proprd1 proprd1 proprd1 proprd1 proprd1 proprd1

10.20.191.76 10.20.191.78 10.20.191.80 10.20.191.82 10.20.191.91 10.20.191.93 10.20.194.57 10.14.104.122 10.14.104.203

798 160 396 99 274 43,839 96 8 9

If the SID column is NULL, then the client has used the Service Name, which is displayed in the next column. This output shows relatively good news. Most of the clients are using Service Name instead of SIDs. This output serves two purposes — (1) you can target the IP addresses shown in the lower portion of the output to change them to service names whenever possible, and (2) you can check the Service Names used by the IP addresses in the upper half if they are accurate.

Mining for Security So far, we have collected information on the database connections that are legitimate. Listener logs also contain information on unsuccessful attempts for connection. Even though not all unsuccessful attempts are attacks, a pattern might emerge from the attempt to show a potential attack. Using the listener mining tool, we can reveal a lot of those issues.

Listener Password When you set a password for the listener, the user must supply the correct password before issuing some damaging commands such as stopping the listener. Note: this behavior is different across Oracle versions. In Oracle 9i and earlier, a password, if set, applies to any user trying to manipulate the listener. In Oracle 10g and later, the Oracle software owner without a password can manipulate the listener. So, if a user other than the software owner tries to manipulate the listener, he has to supply the correct password, else he gets the following error: TNS-01190: The user is not authorized to execute the requested listener command And this message also finds its way to the listener log file such as the following line: 06-NOV-2005 13:45:06 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=prolin01)(USER=ananda ))(COMMAND=stop)(ARGUMENTS=64)(SERVICE=LISTENER_PROLIN01)(VERSION=168821760) ) * stop * 1190 TNS-01190: The user is not authorized to execute the requested listener command We can mine this information from the listener log using our tool. Note an important difference, however. This line has just four fields, not the usual six. Therefore, the field ACTION will show the last field on this line — the return code, i.e., 1190.

col l_user format a10 col service format a20 col logdate format a20 col host format a10 col RC format a5 select to_char(log_date,'mm/dd/yy hh24:mi:ss') logdate, parse_listener_log_line(connect_string,'HOST') host, parse_listener_log_line(connect_string,'USER') l_user, parse_listener_log_line(connect_string,'SERVICE') service, action RC from listener_log where parse_listener_log_line(connect_string, 'COMMAND') = 'stop'; The output is: LOGDATE -------------------10/16/05 05:35:41 10/27/05 21:04:50 11/06/05 13:45:06 11/06/05 13:46:00

HOST ---------prolin01 prolin01 prolin01 prolin01

L_USER ---------oraprol oraprol ananda ananda

SERVICE -------------------LISTENER_PROLIN01 LISTENER_PROLIN01 LISTENER_PROLIN01 LISTENER_PROLIN01

RC ----0 0 1190 0

Read the lines of the previous example carefully. On one occasion, on 11/06/05 13:45:06, the user “ananda” issued the stop command to the listener LISTENER_PROLIN01, without supplying the right password. Does this indicate an attack? The answer lies in the next line. About a minute later, at 13:46, the user probably realized the mistake in the password and supplied the right one and started the listener properly, as shown by the Return Code of “0.” However, if we had seen a number of lines with Return Code 1190, then we would have suspected a possible attack. In addition, we would also have verified that the UNIX user “ananda” is actually a DBA, mapped to a physical person, and upon questioning, we’d have found out that the user was indeed trying to stop the listener, but it failed due to a bad password first time. It all fits together. Here is another example: LOGDATE -------------------10/16/05 05:35:41 10/27/05 21:04:50 11/06/05 13:45:06 11/06/05 13:45:37 11/06/05 13:46:01 11/06/05 13:46:41 11/06/05 13:47:05

HOST ---------prolin01 prolin01 prolin01 prolin01 prolin01 prolin01 prolin01

L_USER ---------oraprol oraprol ananda ananda ananda ananda ananda

SERVICE -------------------LISTENER_PROLIN01 LISTENER_PROLIN01 LISTENER_PROLIN01 LISTENER_PROLIN01 LISTENER_PROLIN01 LISTENER_PROLIN01 LISTENER_PROLIN01

RC ----0 0 1190 1190 1190 1190 1190

This time, we see that the user “ananda” made several attempts to supply the correct password, each within seconds of the other. This could indicate an explainable and benign situation — the user forgot the password and was trying to enter all possible commands. It also indicates a potentially malignant situation, which the user “ananda” was actually trying to break the password and stop the listener illegally. This should warrant attention and further investigation.

Log File Redirection

One of the breaches comes from the exploit available in the listener code, in which case a hacker might change the log directory to something other than the default, and then use that to gain valuable information about the listener, the services, the database, and so on. In a more serious exploit, the hacker might direct certain commands to be placed in the trace files that creates a user and grants it a DBA role. These commands are then placed in the glogin.sql file, which is executed automatically every time someone on the server connects to the database using SQL*Plus. When the DBA logs in, the code is also executed, which creates this Trojan horse user. To prevent such an exploit, you should place a password on the listener. When the user tries to modify these values, the correct password must be specified. If the wrong password is supplied, the user gets a TNS-1190 error, which also goes to the log file. Here are two sample entries in the log file, when an incorrect password was issued: 06-NOV-2005 13:52:33 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=prolin02)(USER=ananda))(COMMAND=log_file) (AR GUMENTS=4)(SERVICE=LISTENER_PROLIN01)(VERSION=168821760)(VALUE=/tmp/a)) * log_file * 1190 06-NOV-2005 14:01:45 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=prolin02)(USER=ananda))(COMMAND=log_direc tor y)(ARGUMENTS=4)(SERVICE=LISTENER_PROLIN01)(VERSION=168821760)(VALUE=/tmp)) * log_directory * 1190 This is also something we can successfully mine from logs using our listener log mining tool. Note that this has only four fields, not six, as in case of a regular listener log line. These four map to the first four fields on the listener log external table, even though the actual column names may be different. So, the meanings of some of the external table columns are different now as shown in the following: Column LOG_DATE CONNECT_STRING PROTOCOL_INFO ACTION

New Meaning Log Date The Connect string, meaning is same The command given by the user (log_file), not the same meaning as protocol_info The return code (1190), not the

Using this understanding, we can write the query to find out who issued the “log_file” command and what was the result: col l_user format a10 col service format a20 col logdate format a20 col host format a10 col RC format a5 select to_char(log_date,'mm/dd/yy hh24:mi:ss') logdate, parse_listener_log_line(connect_string,'HOST') host, parse_listener_log_line(connect_string,'USER') l_user, parse_listener_log_line(connect_string,'SERVICE') service, action RC from listener_log where parse_listener_log_line(connect_string, 'COMMAND') = 'log_file';

This shows the output: LOGDATE HOST L_USER SERVICE RC -------------------- ---------- ---------- -------------------- ----11/06/05 13:52:33 prolin01 ananda LISTENER_PROLIN01 1190 This shows that at the specified time, the user “ananda” tried to change the log file of the listener without supplying the correct password. He must have received the TNS-1190 error, which is what we see in the listener log. This could be an honest mistake, but is definitely worth an investigation.

Admin Restrictions As I explained previously, one of the most common attacks against the database come through the listener by changing the log file to the glogin.sql in the directory $ORACLE_HOME/sqlplus/admin and placing some commands there. However, what if you could restrict the ability to issue the command from the LSNRCTL prompt? You can do so by placing the RESTRICT_ADMIN option in the listener.ora file and restarting the listener. Once this is place, the only way to change the log_file, log_directory, trc_level, and so on, is to change them in the listener.ora file, then reload the listener. If you want to change them online, you will get this error: TNS-12508: TNS:listener could not resolve the COMMAND given The following line will appear in the listener log file: 06-NOV-2005 14:10:20 * trc_level * 12508 TNS-12508: TNS:listener could not resolve the COMMAND given If you search for this error, you can determine whether anyone has attempted to change them online. Note that this has only three fields, not six, as in case of a regular listener log line. These three map to the first three fields on the listener log external table, even though the actual columns names are different. So, meanings of the external table columns may differ as shown: Column LOG_DATE CONNECT_STRING PROTOCOL_INFO

New Meaning Log Date The command given by the user (trc_level) The return code (12508)

We can then write the query to extract the correct information: Col command format a20 Col return_code format a15 Set pages 3400 select log_date, connect_string protocol_info from listener_log where connect_string in (

command, return_code

'password', 'rawmode', 'displaymode', 'trc_file', 'trc_directory', 'trc_level', 'log_file', 'log_directory', 'log_status', 'current_listener', 'inbound_connect_timeout', 'startup_waittime', 'save_config_on_stop', 'start', 'stop', 'status', 'services', 'version', 'reload', 'save_config', 'trace', 'spawn', 'change_password', 'quit', 'exit' ) / This returns the following: LOG_DATE --------06-NOV-05 06-NOV-05 06-NOV-05 06-NOV-05 06-NOV-05 06-NOV-05 06-NOV-05 06-NOV-05 06-NOV-05 06-NOV-05 06-NOV-05 06-NOV-05 06-NOV-05 06-NOV-05 06-NOV-05 06-NOV-05

COMMAND -------------------change_password save_config log_file trc_level save_config_on_stop log_directory log_directory stop stop services status reload status stop status stop

RETURN_CODE --------------0 0 0 12508 12508 12508 12508 1169 1169 1169 1169 1169 1169 1169 1169 1169

The results are interesting. On several occasions, we see that someone has issued the commands without restarting the listener. Some of them may be really benign — they may have been entered by mistake. But that’s something you can easily verify. To verify further, you will need to find out all other details about these commands — the OS userid, the extat time, and so on. You can create a generic query as the following: select log_date, parse_listener_log_line(connect_string,'USER') l_user, protocol_info command, action return_code from listener_log where parse_listener_log_line(connect_string,'COMMAND') in ( 'start', 'stop', 'status', 'services', 'version', 'reload', 'save_config', 'trace','spawn', 'change_password', 'quit', 'exit' ) and action != '0' / The partial output is: LOG_DATE L_USER COMMAND RETURN_CODE --------- --------------- --------------- --------------06-NOV-05 ananda stop 1190 ... ... It appears that the user “ananda” issued a stop command, and received an error 1190, as shown in RETURN_CODE. The full error message the user must have got is: TNS-01190: The user is not authorized to execute the requested listener command Again, this could have been an honest mistake; but it warrants an investigation, nonetheless. If you see a pattern, this may lead to a possible attack.

Combining with Auditing

So far, we have seen how to mine these valuable pieces of information from the listener log alone. There is another source of vital connection information — the database audit trail. This is not turned on by default; you must explicitly enable it by setting the initialization parameter audit_trail to DB_EXTENDED or DB and then restarting the database. When the database is up, issue the following statement: AUDIT CREATE SESSION; This will enable the auditing of all logons and logoffs, but not of any specific statements. After the database has been running for a while, you can see the audit trails in the view DBA_AUDIT_TRAIL. The audit trails are recorded with the timestamp as well; however, the timestamps are made when the database connections are made, and the listener log timestamp is made when the listener gets the request. There is a difference between the two — usually one or two seconds, which we will have to accommodate in the query. You can perform the following query to combine the audit trails and listener log entries: select username, ses_actions, logoff_time, comment_text, sql_text from dba_audit_trail a, listener_log l where parse_listener_log_line(connect_string,'SERVICE_NAME') = 'DBA' and parse_listener_log_line(connect_string,'HOST') = 'STSCOTIGERAT42' and l.log_date between a.timestamp - (2/24/60/60) and a.timestamp and a.terminal = 'STSCOTIGERAT42' / The output is as follows: USERNAME SES_ACTIONS LOGOFF_TI ------------------------------ ------------------- --------COMMENT_TEXT -----------------------------------------------------------------------------SQL_TEXT -----------------------------------------------------------------------------SCOTIGERA Authenticated by: DATABASE; Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=10.14.1 04.72)(PORT=1365))

02-NOV-05

This shows that the user connected as the Oracle userid SCOTIGERA, even though she used the service_name as DBA, so we can rest easy. Now it is time to connect the JDBC connections with service names and userids. The audit trails contain the username, but not the service name, while listener logs have service names, but not usernames. So, we need to combine them to get the complete picture. Remember, from the discussion on tracking client machines, that the host with IP address 10.20.214.170 had the maximum number of connections using thin JDBC drivers? Let’s find out how many service names are used from that client.

First, we need to find out the hostname of the server with that IP Address. We can try to get it by nslookup, provided it’s in the DNS: c:\Work\Orascripts>nslookup 10.20.214.170 Name: stcdelpas01.starwoodhotels.com Address: 10.20.214.170 The name of the client is “stcdelpas01,” which is what appears in the Audit Trails. So, we can combine the Listener Log records with the Audit Trail ones to track the service names used by this client. select parse_listener_log_line(connect_string,'SERVICE_NAME') SN, a.username, count(1) cnt from listener_log l, dba_audit_trail a where parse_listener_log_line(connect_string,'HOST') = '__jdbc__' and parse_listener_log_line(protocol_info,'HOST') = '10.20.214.170' and l.log_date between a.timestamp - (2/24/60/60) and a.timestamp and a.userhost = 'stcdelpas01' group by parse_listener_log_line(connect_string,'SERVICE_NAME'), a.username / From the output, we can ascertain how the usernames and service names are connected from the hostname. This is just an example of how you can combine audit logs and listener logs.

Conclusion As you can see in the previous sections, the listener log contains several valuable pieces of information that can offer insights into the way users connect to the database and how to diagnose common existing, and potential, issues, allowing you to be proactive or at least to gain in-depth knowledge about the database usage. These articles are an introduction to the concept of building this tool, they do not show the full capabilities of this tool or the concept. From this foundation, you can build your own enhancements, with all the sophistication you want. For instance, you can build a scheduler job that polls this table and intelligently sends a server alert if a certain condition is satisfied (e.g., if someone tried to stop the listener several times with a wrong password or to change the log_file, even though the listener is under ADMIN RESTRICT condition, indicating some potential security breach). You can build forms in HTMLDB to present these in some user-friendly format, or even persuade some friendly developer to develop a Web page that shows the data in a nice, formatted manner for all to examine. The possibilities are endless, and I hope I have tickled your imagination. Good luck mining and enhancing this tool. If you do add enhancements to this tool, I would highly appreciate it if you could drop me a line or post a comment to this article. After all, knowledge grows by sharing.

-Arup Nanda has been an Oracle DBA for more than 11 years with a career path spanning all aspects Oracle database design and development – modeling, performance tuning, security, disaster recovery, real application clusters and much more. He speaks frequently at many events such as Oracle World, IOUG Live and writes regularly for publications like Oracle Magazine, DBAzine.com, and Select Journal (the IOUG publication). Recognizing his accomplishments and contributions to the user community, Oracle honored him with the DBA of the Year award in 2003.