Environment
Novell Open Enterprise Server 2 (OES 2) Linux
Novell Open Enterprise Server 11 (OES 11) 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.
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 :
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
- 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
}
/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.