My Oracle Support Banner

Repeated login/logout messages "session opened for user grid by root" in /var/log/secure (Doc ID 2574495.1)

Last updated on NOVEMBER 11, 2020

Applies to:

Oracle Database - Enterprise Edition - Version 12.2.0.1 to 12.2.0.1 [Release 12.2]
Linux x86-64

Symptoms

1. On : 12.2.0.1 RAC/Grid environment, repeated log message has been found in node /var/log/secure log:

Aug 27 23:53:18 <node name>sshd[11570]: pam_unix(sshd:session): session opened for user grid by (uid=0)
Aug 27 23:53:18 <node name>sshd[11572]: Received disconnect from <remote node IP>: 11: disconnected by user
Aug 27 23:53:18 <node name>sshd[11570]: pam_unix(sshd:session): session closed for user grid
Aug 27 23:53:21 <node name>sshd[11584]: Accepted publickey for grid from <remote node IP> port 52558 ssh2
Aug 27 23:53:21 <node name>sshd[11584]: pam_unix(sshd:session): session opened for user grid by (uid=0)
Aug 27 23:53:21 <node name>sshd[11586]: Received disconnect from <remote node IP>: 11: disconnected by user
Aug 27 23:53:21 <node name>sshd[11584]: pam_unix(sshd:session): session closed for user grid
Aug 27 23:53:21 <node name>sshd[11608]: Accepted publickey for grid from <remote node IP> port 52559 ssh2

 2. In the CVU log files, we can find it try to connect to remote node for tasks:

[Worker 3] [ 2019-08-27 23:53:18.093 EDT ] [RuntimeExec.runCommand:298] runCommand: process returns 0
[Worker 3] [ 2019-08-27 23:53:18.093 EDT ] [RuntimeExec.runCommand:325] RunTimeExec: error>
[Worker 3] [ 2019-08-27 23:53:18.093 EDT ] [RuntimeExec.runCommand:351] Returning from RunTimeExec.runCommand
[Worker 3] [ 2019-08-27 23:53:18.093 EDT ] [NativeSystem.isCmdScv:547] isCmdScv: cmd=[/usr/bin/scp -p /tmp/CVU_12.2.0.1.0_resource/getfileinfoconfigfile_832419608000482185.txt <node name>:'/tmp/CVU_12.2.0.1.0_resource/getfileinfoconfigfile_5625562400889886878.txt']
[Worker 3] [ 2019-08-27 23:53:18.093 EDT ] [NativeSystem.isCmdScv:597] isCmdScv: /usr/bin/scp is present.
[Worker 3] [ 2019-08-27 23:53:18.094 EDT ] [NativeSystem.isCmdScv:599] isCmdScv: /usr/bin/scp is a file.
[Worker 3] [ 2019-08-27 23:53:18.094 EDT ] [NativeSystem.isCmdScv:616] isCmdScv: returned true
[Worker 3] [ 2019-08-27 23:53:18.094 EDT ] [NativeSystem.rununixcmd:1283] NativeSystem.rununixcmd: RetString 1| :successful
[Worker 3] [ 2019-08-27 23:53:18.094 EDT ] [NativeResult.<init>:93] NativeResult: The String obtained is1| :successful
[Worker 3] [ 2019-08-27 23:53:18.094 EDT ] [NativeResult.<init>:101] The status string is: 1
[Worker 3] [ 2019-08-27 23:53:18.094 EDT ] [NativeResult.<init>:114] The result string is: :successful 1
[Worker 3] [ 2019-08-27 23:53:18.094 EDT ] [ClusterConfig$ExecuteCommand.returnCommandToClient:3301] returnCommandToClient; fillCount=1 is full=false
[Worker 3] [ 2019-08-27 23:53:18.094 EDT ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread Worker 3 m_count=99
[Worker 3] [ 2019-08-27 23:53:18.094 EDT ] [Semaphore.release:85] SyncBufferFull:Release called by thread Worker 3 m_count=2
[Worker 3] [ 2019-08-27 23:53:18.094 EDT ] [ClientResource.getListener:157] Calling getListener
[Worker 3] [ 2019-08-27 23:53:18.094 EDT ] [ClusterConfig$ExecuteCommand.run:3396] Owner Thread name of the blocking Semaphore main
[Worker 3] [ 2019-08-27 23:53:18.094 EDT ] [ClusterConfig$ExecuteCommand.run:3404] Obtained Semaphore
[Worker 3] [ 2019-08-27 23:53:18.095 EDT ] [Semaphore.release:85] ClientResource Constructor:Blocking Semaphore owned by main:Release called by thread Worker 3 m_count=1
[Worker 3] [ 2019-08-27 23:53:18.095 EDT ] [ClusterConfig$ExecuteCommand.run:3419] Released Semaphore by worker=Worker 3

 

Cause

To view full details, sign in with your My Oracle Support account.

Don't have a My Oracle Support account? Click to get started!


In this Document
Symptoms
Cause
Solution


My Oracle Support provides customers with access to over a million knowledge articles and a vibrant support community of peers and Oracle experts.