Problems with running auditining-sshd

[sambuddho]

Hi All
I am having some problem running auditing-sshd to capture ssh
terminal interactions. I am using the following configuration, as per
the documentation in the google code site:

client --connects_to--> auditing-sshd (isshd) ---> connects to stunnel
(see configuration below) --> connects_to --> ssllogmux (see
configuration below).

I am not running bro-ids as of now and only trying to capture the
shell interactions in a terminal. I do see the various ssl handshake
messages on both stunnel (when run in foreground mode) and ssllogmux
(when run in debug mode (-d option)). However I don't see the capture
shell interactions.

stunnel configuration

socket = l:TCP_NODELAY=1
socket = r:TCP_NODELAY=1
cert = /etc/stunnel/stunnel.pem
client=yes
#debug = 5
debug = 7
pid=/var/run/syslog_c2.pid
#output=/tmp/stunnel_client.log
#foreground = no
foreground = yes

[syslog-client]
accept = 127.0.0.1:799
connect = 127.0.0.1:1799

This is nearly the same as that described on the wiki page. I am
running ssllogmux with the following command line options :
./ssllogmux -c /etc/stunnel/stunnel.pem -k /etc/stunnel/stunnel.pem -f
-d

stunnel4 debug logs:

2012.01.19 16:57:58 LOG7[13712:3083376304]: Snagged 64 random bytes
from /root/.rnd
2012.01.19 16:57:58 LOG7[13712:3083376304]: Wrote 1024 new random
bytes to /root/.rnd
2012.01.19 16:57:58 LOG7[13712:3083376304]: RAND_status claims
sufficient entropy for the PRNG
2012.01.19 16:57:58 LOG7[13712:3083376304]: PRNG seeded successfully
2012.01.19 16:57:58 LOG7[13712:3083376304]: Certificate: /etc/stunnel/
stunnel.pem
2012.01.19 16:57:58 LOG7[13712:3083376304]: Certificate loaded
2012.01.19 16:57:58 LOG7[13712:3083376304]: Key file: /etc/stunnel/
stunnel.pem
2012.01.19 16:57:58 LOG7[13712:3083376304]: Private key loaded
2012.01.19 16:57:58 LOG7[13712:3083376304]: SSL context initialized
for service syslog-client
2012.01.19 16:57:58 LOG5[13712:3083376304]: stunnel 4.21 on i486-pc-
linux-gnu with OpenSSL 0.9.8g 19 Oct 2007
2012.01.19 16:57:58 LOG5[13712:3083376304]: Threading:PTHREAD
SSL:ENGINE Sockets:POLL,IPv6 Auth:LIBWRAP
2012.01.19 16:57:58 LOG6[13712:3083376304]: file ulimit = 1024 (can be
changed with 'ulimit -n')
2012.01.19 16:57:58 LOG6[13712:3083376304]: poll() used - no
FD_SETSIZE limit for file descriptors
2012.01.19 16:57:58 LOG5[13712:3083376304]: 500 clients allowed
2012.01.19 16:57:58 LOG7[13712:3083376304]: FD 8 in non-blocking mode
2012.01.19 16:57:58 LOG7[13712:3083376304]: FD 9 in non-blocking mode
2012.01.19 16:57:58 LOG7[13712:3083376304]: FD 10 in non-blocking mode
2012.01.19 16:57:58 LOG7[13712:3083376304]: SO_REUSEADDR option set on
accept socket
2012.01.19 16:57:58 LOG7[13712:3083376304]: syslog-client bound to
127.0.0.1:799
2012.01.19 16:57:58 LOG7[13712:3083376304]: Created pid file /var/run/
syslog_c2.pid
2012.01.19 16:58:28 LOG7[13712:3083376304]: syslog-client accepted
FD=11 from 127.0.0.1:52179
2012.01.19 16:58:28 LOG7[13712:3083373456]: syslog-client started
2012.01.19 16:58:28 LOG7[13712:3083373456]: FD 11 in non-blocking mode
2012.01.19 16:58:28 LOG7[13712:3083373456]: TCP_NODELAY option set on
local socket
2012.01.19 16:58:28 LOG7[13712:3083373456]: Waiting for a libwrap
process
2012.01.19 16:58:28 LOG7[13712:3083373456]: Acquired libwrap process
#0
2012.01.19 16:58:28 LOG7[13712:3083373456]: Releasing libwrap process
#0
2012.01.19 16:58:28 LOG7[13712:3083373456]: Released libwrap process
#0
2012.01.19 16:58:28 LOG7[13712:3083373456]: syslog-client permitted by
libwrap from 127.0.0.1:52179
2012.01.19 16:58:28 LOG5[13712:3083373456]: syslog-client accepted
connection from 127.0.0.1:52179
2012.01.19 16:58:28 LOG7[13712:3083373456]: FD 12 in non-blocking mode
2012.01.19 16:58:28 LOG7[13712:3083373456]: syslog-client connecting
127.0.0.1:1799
2012.01.19 16:58:28 LOG7[13712:3083373456]: connect_wait: waiting 10
seconds
2012.01.19 16:58:28 LOG7[13712:3083373456]: connect_wait: connected
2012.01.19 16:58:28 LOG5[13712:3083373456]: syslog-client connected
remote server from 127.0.0.1:53791
2012.01.19 16:58:28 LOG7[13712:3083373456]: Remote FD=12 initialized
2012.01.19 16:58:28 LOG7[13712:3083373456]: TCP_NODELAY option set on
remote socket
2012.01.19 16:58:28 LOG7[13712:3083373456]: SSL state (connect):
before/connect initialization
2012.01.19 16:58:28 LOG7[13712:3083373456]: SSL state (connect): SSLv3
write client hello A
2012.01.19 16:58:28 LOG7[13712:3083373456]: SSL state (connect): SSLv3
read server hello A
2012.01.19 16:58:28 LOG7[13712:3083373456]: SSL state (connect): SSLv3
read server certificate A
2012.01.19 16:58:28 LOG7[13712:3083373456]: SSL state (connect): SSLv3
read server done A
2012.01.19 16:58:28 LOG7[13712:3083373456]: SSL state (connect): SSLv3
write client key exchange A
2012.01.19 16:58:28 LOG7[13712:3083373456]: SSL state (connect): SSLv3
write change cipher spec A
2012.01.19 16:58:28 LOG7[13712:3083373456]: SSL state (connect): SSLv3
write finished A
2012.01.19 16:58:28 LOG7[13712:3083373456]: SSL state (connect): SSLv3
flush data
2012.01.19 16:58:28 LOG7[13712:3083373456]: SSL state (connect): SSLv3
read finished A
2012.01.19 16:58:28 LOG7[13712:3083373456]: 1 items in the session
cache
2012.01.19 16:58:28 LOG7[13712:3083373456]: 1 client connects
(SSL_connect())
2012.01.19 16:58:28 LOG7[13712:3083373456]: 1 client connects that
finished
2012.01.19 16:58:28 LOG7[13712:3083373456]: 0 client renegotiations
requested
2012.01.19 16:58:28 LOG7[13712:3083373456]: 0 server connects
(SSL_accept())
2012.01.19 16:58:28 LOG7[13712:3083373456]: 0 server connects that
finished
2012.01.19 16:58:28 LOG7[13712:3083373456]: 0 server renegotiations
requested
2012.01.19 16:58:28 LOG7[13712:3083373456]: 0 session cache hits
2012.01.19 16:58:28 LOG7[13712:3083373456]: 0 session cache misses
2012.01.19 16:58:28 LOG7[13712:3083373456]: 0 session cache
timeouts
2012.01.19 16:58:28 LOG6[13712:3083373456]: SSL connected: new session
negotiated
2012.01.19 16:58:28 LOG6[13712:3083373456]: Negotiated ciphers: AES256-
SHA SSLv3 Kx=RSA Au=RSA Enc=AES(256) Mac=SHA1
2012.01.19 16:58:28 LOG7[13712:3083376304]: syslog-client accepted
FD=13 from 127.0.0.1:52181
2012.01.19 16:58:28 LOG7[13712:3083303824]: syslog-client started
2012.01.19 16:58:28 LOG7[13712:3083303824]: FD 13 in non-blocking mode
2012.01.19 16:58:28 LOG7[13712:3083303824]: TCP_NODELAY option set on
local socket
2012.01.19 16:58:28 LOG7[13712:3083303824]: Waiting for a libwrap
process
2012.01.19 16:58:28 LOG7[13712:3083303824]: Acquired libwrap process
#0
2012.01.19 16:58:28 LOG7[13712:3083303824]: Releasing libwrap process
#0
2012.01.19 16:58:28 LOG7[13712:3083303824]: Released libwrap process
#0
2012.01.19 16:58:28 LOG7[13712:3083303824]: syslog-client permitted by
libwrap from 127.0.0.1:52181
2012.01.19 16:58:28 LOG5[13712:3083303824]: syslog-client accepted
connection from 127.0.0.1:52181
2012.01.19 16:58:28 LOG7[13712:3083303824]: FD 14 in non-blocking mode
2012.01.19 16:58:28 LOG7[13712:3083303824]: syslog-client connecting
127.0.0.1:1799
2012.01.19 16:58:28 LOG7[13712:3083303824]: connect_wait: waiting 10
seconds
2012.01.19 16:58:28 LOG7[13712:3083303824]: connect_wait: connected
2012.01.19 16:58:28 LOG5[13712:3083303824]: syslog-client connected
remote server from 127.0.0.1:53793
2012.01.19 16:58:28 LOG7[13712:3083303824]: Remote FD=14 initialized
2012.01.19 16:58:28 LOG7[13712:3083303824]: TCP_NODELAY option set on
remote socket
2012.01.19 16:58:28 LOG7[13712:3083303824]: SSL state (connect):
before/connect initialization
2012.01.19 16:58:28 LOG7[13712:3083303824]: SSL state (connect): SSLv3
write client hello A
2012.01.19 16:58:28 LOG7[13712:3083303824]: SSL state (connect): SSLv3
read server hello A
2012.01.19 16:58:28 LOG7[13712:3083303824]: SSL state (connect): SSLv3
read server certificate A
2012.01.19 16:58:28 LOG7[13712:3083303824]: SSL state (connect): SSLv3
read server done A
2012.01.19 16:58:28 LOG7[13712:3083303824]: SSL state (connect): SSLv3
write client key exchange A
2012.01.19 16:58:28 LOG7[13712:3083303824]: SSL state (connect): SSLv3
write change cipher spec A
2012.01.19 16:58:28 LOG7[13712:3083303824]: SSL state (connect): SSLv3
write finished A
2012.01.19 16:58:28 LOG7[13712:3083303824]: SSL state (connect): SSLv3
flush data
2012.01.19 16:58:28 LOG7[13712:3083303824]: SSL state (connect): SSLv3
read finished A
2012.01.19 16:58:28 LOG7[13712:3083303824]: 2 items in the session
cache
2012.01.19 16:58:28 LOG7[13712:3083303824]: 2 client connects
(SSL_connect())
2012.01.19 16:58:28 LOG7[13712:3083303824]: 2 client connects that
finished
2012.01.19 16:58:28 LOG7[13712:3083303824]: 0 client renegotiations
requested
2012.01.19 16:58:28 LOG7[13712:3083303824]: 0 server connects
(SSL_accept())
2012.01.19 16:58:28 LOG7[13712:3083303824]: 0 server connects that
finished
2012.01.19 16:58:28 LOG7[13712:3083303824]: 0 server renegotiations
requested
2012.01.19 16:58:28 LOG7[13712:3083303824]: 0 session cache hits
2012.01.19 16:58:28 LOG7[13712:3083303824]: 0 session cache misses
2012.01.19 16:58:28 LOG7[13712:3083303824]: 0 session cache
timeouts
2012.01.19 16:58:28 LOG6[13712:3083303824]: SSL connected: new session
negotiated
2012.01.19 16:58:28 LOG6[13712:3083303824]: Negotiated ciphers: AES256-
SHA SSLv3 Kx=RSA Au=RSA Enc=AES(256) Mac=SHA1
2012.01.19 17:05:45 LOG3[13712:3083376304]: Received signal 2;
terminating
2012.01.19 17:05:45 LOG7[13712:3083376304]: removing pid file /var/run/
syslog_c2.pid


ssllogmux debug messages:

DEBUG: .../IO/Socket/SSL.pm:1545: new ctx 140675192
DEBUG: .../IO/Socket/SSL.pm:1008: start handshake
DEBUG: .../IO/Socket/SSL.pm:507: starting sslifying
DEBUG: .../IO/Socket/SSL.pm:547: Net::SSLeay::accept -> 1
DEBUG: .../IO/Socket/SSL.pm:595: handshake done, socket ready
DEBUG: .../IO/Socket/SSL.pm:1545: new ctx 140783224
DEBUG: .../IO/Socket/SSL.pm:1008: start handshake
DEBUG: .../IO/Socket/SSL.pm:507: starting sslifying
DEBUG: .../IO/Socket/SSL.pm:547: Net::SSLeay::accept -> 1
DEBUG: .../IO/Socket/SSL.pm:595: handshake done, socket ready
DEBUG: .../IO/Socket/SSL.pm:1582: free ctx 140783224 open=140675192
140783224
DEBUG: .../IO/Socket/SSL.pm:1590: OK free ctx 140783224
DEBUG: .../IO/Socket/SSL.pm:1582: free ctx 140675192 open=140675192
DEBUG: .../IO/Socket/SSL.pm:1590: OK free ctx 140675192



Thanks
Sambuddho

[Scott Campbell]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Hello!

When you have the isshd running, does a 'netstat -an' provide any
indications that there is a connection from the sshd to the local
799/tcp? Also, are there any messages as provided by syslog?

If you are just interested in seeing the output directly from the sshd
process, there is a line in nersc.c which you can uncomment which will
print the event stream to stderr. It is line 466 which looks like:

/*write(STDERR_FILENO, fmtbuf, strlen(fmtbuf)); */

cheers,
scott

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Darwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iD8DBQFPGJraK2Plq8B7ZBwRApHiAKCrTxGGjM0kqAyGxAtKlSrnttImwACfTkPn
YlYxkh0/uW93cdxwHRnISkY=
=pVhs
-----END PGP SIGNATURE-----

[sambuddho]

Hello Scott!
Thanks for your prompt reply. Yes I do see connections to localhost/
799 and to localhost/1799 (the ssllogmux listen process). I also have
syslog messages showing whenever there is connection from the stunnel
to the ssllogmux process. A snippet from those logs is as follows:

Jan 19 17:59:32 nsl-vmuser-5 ./ssllogmux[28610][28610]: starting
listener
Jan 19 17:59:44 nsl-vmuser-5 ./ssllogmux[28610][28610]: New client at
127.0.0.1:47010
Jan 19 17:59:44 nsl-vmuser-5 ./ssllogmux[28610][28610]: New client at
127.0.0.1:47011
Jan 19 18:00:01 nsl-vmuser-5 ./ssllogmux[28610][28610]: Closing socket
from 127.0.0.1:47011
Jan 19 18:00:05 nsl-vmuser-5 ./ssllogmux[28610][28610]: Exitting on
signal SIGINT.
Jan 19 18:00:56 nsl-vmuser-5 ./ssllogmux[21689][21689]: starting
listener
Jan 19 18:02:38 nsl-vmuser-5 ./ssllogmux[21162][21162]: starting
listener

But I still don't see output going to the text file or being printed
to stderr/stdout. The debug output only shows me SSL handshake
messages(as shown above).

Thanks
Sambuddho

> ...
>
> read more »