Our site suffered the crash of an Avaloq test database. The following information was found in the alert log:<\/p>\n
PMON (ospid: 1112): terminating the instance due to error 471\r\nTIMESTAMP\r\nSystem state dump requested by (instance=1, osid=1112 (PMON)), summary=[abnormal instance termination].\r\nSystem State dumped to trace file \/u00\/oracle\/orabase\/diag\/rdbms\/XXX\/trace\/XXX_diag_1221_20151231063902.trc\r\nDumping diagnostic data in directory=[cdmp_20151231063902], requested by (instance=1, osid=1112 (PMON)), summary=[abnormal instance termination].\r\nInstance terminated by PMON, pid = 1112<\/code><\/pre>\nI looked into the pmon trace XXX_pmon_1112.trc and found out that the PMON terminated the instance because the database writer process DBW2 was not running any more:<\/p>\n
Background process DBW2 found dead\r\nOracle pid = 12\r\nOS pid (from detached process) = 1234\r\nOS pid (from process state) = 1234\r\n<\/code><\/pre>\nNote here the OS pid of the DBW process – 1234. This is an important clue for later.<\/p>\n
There weren’t any trace files left by the process 1234, so I assumed that the sudden death was due to some external impact. To find out the cause I used the kill.d<\/a> dtrace script by Gregg Brendan<\/a>. The culprit was indeed revealed next day when I harvested the kill.d results :<\/p>\n...\r\n26804 aaafile.sh 9 1234 -1\r\n27913 aaafile.sh 9 1234 -1\r\n28988 aaafile.sh 9 1234 -1\r\n28509 aaafile.sh 9 1234 -1\r\n27393 aaafile.sh 9 1234 -1\r\n29964 aaafile.sh 9 1234 -1\r\n...\r\n<\/code><\/pre>\nThe avaloq program aaafile.sh was killing the 1234 process. In this case, the victim happened to be a database writer.<\/p>\n
But why would Avaloq do this?<\/p>\n
To answer this question I correlated the information in alert log with the Avaloq aaafile log files.<\/p>\n
Thu Jan 07 15:19:58 2016\r\nALTER SYSTEM enable restricted session;\r\nImmediate Kill Session#: 811, Serial#: 3\r\nImmediate Kill Session: sess: 316711c00 OS pid: 12280\r\nImmediate Kill Session#: 1084, Serial#: 77\r\nImmediate Kill Session: sess: 314742c68 OS pid: 11927\r\nImmediate Kill Session#: 1142, Serial#: 1179\r\nImmediate Kill Session: sess: 3167a1f68 OS pid: 12020\r\nThu Jan 07 15:20:01 2016\r\nopiodr aborting process unknown ospid (12068) as a result of ORA-28\r\nThu Jan 07 15:20:22 2016\r\nopidrv aborting process J099 ospid (28486) as a result of ORA-28\r\nThu Jan 07 15:23:30 2016\r\nCompleted checkpoint up to RBA [0xd.2.10], SCN: 85281115086\r\n<\/code><\/pre>\naaafile log:\r\nsvavr02a:2016-01-07_15-20:\"\":INFO: PARAMS: CMD = kill, FILE = 1234\r\n...\r\nsvavr02a:2016-01-07_15-20:\"\":INFO: Processing Command: kill process (1234)\r\nkill: 1234: no such process\r\n...\r\nsvavr02a:2016-01-07_15-20:\"\":INFO: PARAMS: CMD = kill, FILE = 12112\r\n...\r\nsvavr02a:2016-01-07_15-20:\"\":INFO: Processing Command: kill process (12112)\r\n...\r\nsvavr02a:2016-01-07_15-20:\"\":INFO: PARAMS: CMD = kill, FILE = 1234\r\n...\r\nsvavr02a:2016-01-07_15-20:\"\":INFO: Processing Command: kill process (1234)\r\nkill: 1234: no such process\r\n...\r\nsvavr02a:2016-01-07_15-20:\"\":INFO: PARAMS: CMD = kill, FILE = 28486\r\n...\r\nsvavr02a:2016-01-07_15-20:\"\":INFO: Processing Command: kill process (28486)\r\n<\/code><\/pre>\nFrom the information above the following can be deduced:
\n– the session and os kills were caused by setting the session level 0 (session level 0 is the application shutdown in Avaloq)
\n– every database session kill was followed by the kill -9 of the corresponding shadow process
\n– there were a lot of kill -9 1234 for no obvious reason<\/p>\n
To find out where the kill -9 1234 was coming from, I traced the session which sets the session level to zero and found the following query on the v$process view:<\/p>\n
SELECT P.SPID\r\n ,S.PROCESS\r\n ,S.MACHINE\r\n ,S.PROGRAM\r\n FROM V$SESSION S\r\n ,V$PROCESS P\r\n WHERE S.SID = :b0\r\n AND S.SERIAL# = :b1\r\n AND P.ADDR (+) = S.PADDR;\r\n<\/code><\/pre>\nThis query was executed after almost every alter system disconnect session immediate.<\/p>\n
Therefore, I concluded that Avaloq is quering the v$process.spid to find out the OS PID. However, as kill oracle session and kill -9 ar not atomic operations it can happen that the shadow process already disappears when by the time the query gets executed returning NULL for SPID.<\/p>\n
Since Avaloq selects v$session.process in the same query I assumed that this value is used as a fallback if SPID is NULL. In the Oracle Documentation<\/a> the column process is described as: “Operating system client process ID”. However, when I selected process from v$session I was suprised to see that for all the JDBC processes the value was set to 1234. The Metalink note “How to Set V$SESSION Properties Using the JDBC Thin Driver (Doc ID 147413.1)” explains that this is the expected behaviour. Hence, Avaloq will kill any process with this PID, if there are JDBC sessions coming from the database server itself. Avaloq doesn’t try to kill all the sessions, but just the ones from the users which are registered in the table SEC_USER. In our case it was the messaging agent which was logged in as user I. In particular, below is the query found in the trace files which selects the sessions for killing:<\/p>\nSELECT SID SID\r\n,SERIAL# SERIAL\r\nFROM GV$SESSION\r\nWHERE AUDSID > 0\r\nAND AUDSID != USERENV('sessionid')\r\nAND TYPE = 'USER'\r\nAND ',' || :b0 || ',' NOT LIKE '%,' || USERNAME || ',%'\r\nAND USERNAME IN (\r\nSELECT ORACLE_USER\r\nFROM SEC_USER\r\nWHERE ORACLE_USER NOT IN ('SYS', 'K', 'K_READ')\r\n)\r\nAND NVL(CLIENT_INFO,' ') NOT LIKE 'BGP_OS.%'\r\nAND PROGRAM NOT LIKE 'amqzlaa%';\r\n<\/code><\/pre>\nAs a workaround, make sure that you close the JDBC connections of the users in K.SEC_USER – except for K, K_READ and SYS – coming from the database server prior to setting session level to zero.<\/p>\n
Update 02\/02\/2016<\/strong>: Avaloq released the patch #1695233 in the release 3.9.1.5.0. The patch recreates the procedure k.kill_session. The patch is successfully tested in my envoironment.<\/p>\n","protected":false},"excerpt":{"rendered":"Setting session level to zero can crash the database if there are local JDBC connections from the application users (i.e. users that are registered in K.SEC_USER and at the same time a core database background process is running under the PID 1234. Continue Reading