ncpserv.log file growing to excessive file sizes and containing non-ascii characters

  • 7008702
  • 05-Jun-2012
  • 28-Aug-2012

Environment

Novell Open Enterprise Server 2 (OES 2) Linux
Novell Open Enterprise Server 11 (OES 11) Linux

Situation

In customer environments it was found that the the /var/opt/novell/log/ncpserv.log was growing to excessive file sizes.

For example :
server:/var/opt/novell/log # ls -ll
total 90867640
lrwxrwxrwx 1 root root          31 Feb 13 12:44 afptcp.log ->
../../../log/afptcpd/afptcp.log
lrwxrwxrwx 1 root root          22 Feb 13 12:44 cifs.log ->
/var/log/cifs/cifs.log
drwxr-xr-x 2 root root        4096 Feb  9 23:43 dfs
---------- 1 root root           0 Feb 13 15:05 libnrm2ncp.log
---------- 1 root root        1153 Mar  1 10:41 ncp2nss.audit.log
---------- 1 root root       12247 Mar  1 10:41 ncp2nss.log
---------- 1 root root         639 Mar  1 10:40 ncpcon.log
---------- 1 root root      583050 Mar  1 11:16 ncpserv.audit.log
---------- 1 root root 82819571712 Mar  7 20:25 ncpserv.log
---------- 1 root root     3620181 Feb 28 15:19 ncpserv.log-20120228.bz2
---------- 1 root root     5386117 Feb 29 15:32 ncpserv.log-20120229.bz2
---------- 1 root root     3526596 Mar  1 15:33 ncpserv.log-20120301.bz2
---------- 1 root root    10826126 Mar  2 16:19 ncpserv.log-20120302.bz2
---------- 1 root root     6129452 Mar  3 15:32 ncpserv.log-20120303.bz2
---------- 1 root root  9084674048 Mar  4 15:21 ncpserv.log-20120304
---------- 1 root root           0 Mar  5 15:15 ncpserv.log-20120305
---------- 1 root root  7744536576 Mar  6 15:16 ncpserv.log-20120306
---------- 1 root root           0 Mar  7 15:15 ncpserv.log-20120307
drwxr-xr-x 2 root root        4096 Mar  2 18:17 ncs
drwxr-xr-x 4 root root        4096 Feb 13 12:44 nss
drwxr-xr-x 7 root root        4096 Feb 13 12:44 oes
drwxr-xr-x 2 root root        4096 Feb 13 15:03 proxymgmt
drwxrwxr-x 2 root root        4096 Mar  1 15:52 sms
server:/var/opt/novell/log #


When the actual logrotate is performed, the file is to be copied to a new file, and the actual copy is processed (compressed and renamed) by logrotate, after which the original file is truncated to 0 bytes again. The problem was that shortly after the logrotate was executed, ncpserv.log started to grow again with the file size it had before it was truncated.

When this happened, it was also found the ncpserv.log file was filled with non-ascii characters and ncpserv.log file could no longer be opened using a regular text editor. Using hexdump tool we determined the file was filled with zero's in large parts of the file.

The regular nightly logrotate upkeep did appear to work properly however.

Resolution

The problem has been resolved, and the customers suffering this problem have been provided with an ftf to confirm the solution.

Successful confirmation has been obtained, and the solution is targeted to be released to the general public in an upcoming Scheduled Maintenance patch for both OES2 and OES11.

Update :
The solution has publicly been released with  the following updates :
- July 2012 Scheduled Maintenance for OES2SP3 - 8242
- July 2012 Scheduled Maintenance for OES11 - 6497

Cause

As NCP runs within the NDSD address space, we have determined that once the NDSD was writing to the /var/opt/novell/log/ncpserv.log file when the actual file was rotated, and it continued to write to the /var/opt/novell/log/ncpserv.log file at the offset where it was during the logrotate action.

Additional Information


The default logrotate configuration for NCP is found under '/etc/logrotate.d/novell-ncpserv-log' which is soft-linked to '/etc/opt/novell/ncp/ncpserv.log.conf'

77160:/etc/logrotate.d # cat novell-ncpserv-log
/var/opt/novell/log/ncpserv.log {
    rotate 5
    notifempty
    compress
    dateext
    size=16M
    copytruncate
}


It must be stated that by default the logrotate runs daily, once every 24h. During these 24 hours the ncpserv.log log file can grow to file sizes beyond what is configured as default, until logrotate executes again.
The daily logrotate action gets invoked as specified in '/etc/cron.daily/logrotate'. We can manually verify when logrotate has last been executed successfully by initiating the following :

77160:/etc/logrotate.d # ls -l /var/spool/cron/lastrun/cron.daily
-rw-r--r-- 1 root root 0 2012-06-05 10:30 /var/spool/cron/lastrun/cron.daily
77160:/etc/logrotate.d #


Note of consideration : It has also been observed that during testing the '/var' file system was filled up to a point where it was running out of free space.

When the '/var' file system runs out of free space, and the free space that is left is not sufficient to copy the ncpserv.log file and process the same with logrotate, the logrotate event will not take place until free space is added or the /var file system is cleaned up.