ISE 2.4 P4: "Buffer messages when server is down" doesn't seem to be working

[Nadav]

Hi everyone,

I'm checking out the buffered remote syslog target functionality. I've configured both MnTs as remote syslog targets for TCP, with a 100MB buffer. The test is as follows:

1) Have a PSN work as normal authenticating several supplicants at a time

2) Block all traffic between PSN and MnT nodes (two-way) for 30 minutes via ACL

3) Unblock all traffic between PSN and MnT nodes

During this time PSN has made thousands of authentications which should be buffered. When the ACL is in place between PSNs and MnTs, the RADIUS Livelog and RADIUS Authentication reports don't show the supposedly buffered PSN authentications, even after 10 minutes of waiting.

I expected that after removing the ACL, I would see not only new PSN authentications but also the syslogs from the past half an hour or so. What happens instead is that I simply see the new authentications from the time I removed the ACL.

I've done this test for both TCP Syslog and Secure Syslog to the MnT servers. 

i) Any ideas if I'm testing this functionality correctly and indeed there is a bug?

ii) Should I need to wait a longer period of time before the missing syslogs appear in the reports?

iii) Is there a way to see within the logs that buffered syslog messages are being sent to the newly discovered remote syslog target (MnTs)?

iv) Can I see how much of the syslog buffer is in use?

Thanks!

[hslai]

I need try some more and, if needed, then check with our team.

I did two tests, using Kiwi Syslog Server:

1. sent only 2 ~ 3 auth requests during the TCP syslogd down. 
2. sent ~ 30 auth requests during the TCP syslogd down.

Only test 1 the TCP syslogd got the requests during the down time in the log viewer, although test 2 showed the messages sent down to the wire. I enabled DEBUG on runtime-logging but found some info on "send queue size":

SyslogTCP,2018-12-18 04:25:37,603,DEBUG,0x7fbe0abdb700,SyslogBaseTCPConnection::handle_output - last send queue size=0, current send queue size=0,SyslogBaseTCPConnection.cpp:298
SyslogTCP,2018-12-18 04:25:37,604,DEBUG,0x7fbe0abdb700,SyslogBaseTCPConnection::handle_output - some data was acknowledged from the last checkpoint or the queue was empty, reschedule timer. New send queue size=2208,SyslogBaseTCPConnection.cpp:319
SyslogTCP,2018-12-18 04:28:08,139,DEBUG,0x7fbe0abdb700,SyslogBaseTCPConnection::handle_output - last send queue size=2208, current send queue size=0,SyslogBaseTCPConnection.cpp:298
SyslogTCP,2018-12-18 04:28:08,140,DEBUG,0x7fbe0abdb700,SyslogBaseTCPConnection::handle_output - some data was acknowledged from the last checkpoint or the queue was empty, reschedule timer. New send queue size=0,SyslogBaseTCPConnection.cpp:319
SyslogTCP,2018-12-18 04:30:38,226,DEBUG,0x7fbe0abdb700,SyslogBaseTCPConnection::handle_output - last send queue size=0, current send queue size=0,SyslogBaseTCPConnection.cpp:298
SyslogTCP,2018-12-18 04:30:38,227,DEBUG,0x7fbe0abdb700,SyslogBaseTCPConnection::handle_output - some data was acknowledged from the last checkpoint or the queue was empty, reschedule timer. New send queue size=1518,SyslogBaseTCPConnection.cpp:319
SyslogTCP,2018-12-18 04:44:10,342,DEBUG,0x7fbe0abdb700,SyslogBaseTCPConnection::handle_output - last send queue size=1518, current send queue size=0,SyslogBaseTCPConnection.cpp:298
SyslogTCP,2018-12-18 04:44:10,342,DEBUG,0x7fbe0abdb700,SyslogBaseTCPConnection::handle_output - some data was acknowledged from the last checkpoint or the queue was empty, reschedule timer. New send queue size=52280,SyslogBaseTCPConnection.cpp:319
SyslogTCP,2018-12-18 04:45:10,701,DEBUG,0x7fbe0abdb700,SyslogBaseTCPConnection::handle_output - last send queue size=52280, current send queue size=0,SyslogBaseTCPConnection.cpp:298
SyslogTCP,2018-12-18 04:45:10,701,DEBUG,0x7fbe0abdb700,SyslogBaseTCPConnection::handle_output - some data was acknowledged from the last checkpoint or the queue was empty, reschedule timer. New send queue size=0,SyslogBaseTCPConnection.cpp:319
SyslogTCP,2018-12-18 04:46:10,936,DEBUG,0x7fbe0abdb700,SyslogBaseTCPConnection::handle_output - last send queue size=0, current send queue size=0,SyslogBaseTCPConnection.cpp:298
SyslogTCP,2018-12-18 04:46:10,936,DEBUG,0x7fbe0abdb700,SyslogBaseTCPConnection::handle_output - some data was acknowledged from the last checkpoint or the queue was empty, reschedule timer. New send queue size=4414,SyslogBaseTCPConnection.cpp:319

PS: If you already engaged Cisco TAC, please let me know the case number.

[Nadav]

Hi @hslai,

So just to be clear, you weren't able to replicate the issue with these tests?

[hslai]

Yes and no. I did not see the messages in the kiwi syslog viewer while the tcpdump showing they were sent.