{"action":"created","issue":{"url":"https://api.github.com/repos/logrotate/logrotate/issues/197","repository_url":"https://api.github.com/repos/logrotate/logrotate","labels_url":"https://api.github.com/repos/logrotate/logrotate/issues/197/labels{/name}","comments_url":"https://api.github.com/repos/logrotate/logrotate/issues/197/comments","events_url":"https://api.github.com/repos/logrotate/logrotate/issues/197/events","html_url":"https://github.com/logrotate/logrotate/issues/197","id":319730678,"number":197,"title":"Error Renaming logrotate.status.tmp File","user":{"login":"histamineblkr","id":5628330,"avatar_url":"https://avatars2.githubusercontent.com/u/5628330?v=4","gravatar_id":"","url":"https://api.github.com/users/histamineblkr","html_url":"https://github.com/histamineblkr","followers_url":"https://api.github.com/users/histamineblkr/followers","following_url":"https://api.github.com/users/histamineblkr/following{/other_user}","gists_url":"https://api.github.com/users/histamineblkr/gists{/gist_id}","starred_url":"https://api.github.com/users/histamineblkr/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/histamineblkr/subscriptions","organizations_url":"https://api.github.com/users/histamineblkr/orgs","repos_url":"https://api.github.com/users/histamineblkr/repos","events_url":"https://api.github.com/users/histamineblkr/events{/privacy}","received_events_url":"https://api.github.com/users/histamineblkr/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":7,"created_at":"2018-05-02T22:14:56Z","updated_at":"2018-05-16T10:51:54Z","closed_at":null,"author_association":"NONE","body":"# Renaming Error\r\nThere seems to be this intermittent renaming error that I am experiencing on only one server. It also seems to happen more frequently in the mornings from 3am to 10am. However, I haven't been able to determine any real pattern or cause. \r\nLogrotate seems to be rotating the logs so I'm not reporting anything about that functionality. I'm just unsure if it rotates when the intermittent error happens.\r\n\r\n## Info\r\n**version:** logrotate-3.7.8-28.el6.x86_64\r\n**os:** CentOS 6.3\r\n**error:** error renaming temp state file /var/lib/logrotate.status.tmp\r\n**use:** A cron job invoked every 15 minutes\r\n\r\n## What I've Tried\r\n### Manual Run with Verbosity \r\nI ran it manually with `logrotate -v /etc/logrotate.conf`, which produced no noticeable errors.\r\n\r\n### Specified a State File\r\nI tried explicitly running with the `-s` flag `logrotate -s /tmp/logrotate /etc/logrotate.conf`. The error persisted.\r\n\r\n### Removing the Logrotate Status File\r\nI removed the `/var/lib/logrotate.status` file and then used `logrotate -f /etc/logrotate.d/syslog` to create a new one. This was from an old bug [here](https://bugzilla.redhat.com/show_bug.cgi?id=447022) I thought may solve the issue. It did not.\r\n\r\n### STraced\r\nI went ahead and straced it and this gave me some insight into what was happening.\r\nNote: the elipses is /etc/localtime and is many lines so I left out for clarity as it doesn't seem to have anything to do with the logrotate.status errors.\r\n\r\n#### Error Run\r\n```\r\nstat(\"/var/lib/logrotate.status\", {st_mode=S_IFREG|0644, st_size=928, ...}) = 0\r\n09:30:01 open(\"/var/lib/logrotate.status\", O_RDONLY) = 3\r\n09:30:01 fstat(3, {st_mode=S_IFREG|0644, st_size=928, ...}) = 0\r\n09:30:01 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f82e27cf000\r\n09:30:01 read(3, \"logrotate state -- version 2\\n\\\"/v\"..., 4096) = 928\r\n...\r\n...\r\n09:30:01 unlink(\"/var/lib/logrotate.status.tmp\") = 0\r\n09:30:01 open(\"/var/lib/logrotate.status\", O_RDONLY) = 3\r\n09:30:01 fgetxattr(3, \"system.posix_acl_access\", 0x7fff0210a910, 132) = -1 EOPNOTSUPP (Operation not supported)\r\n09:30:01 close(3)                       = 0\r\n09:30:01 stat(\"/var/lib/logrotate.status\", {st_mode=S_IFREG|0644, st_size=928, ...}) = 0\r\n09:30:01 umask(0777)                    = 022\r\n09:30:01 getpid()                       = 17898\r\n09:30:01 open(\"/var/lib/logrotate_temp.qY37wE\", O_RDWR|O_CREAT|O_EXCL, 0600) = 3\r\n09:30:01 umask(022)                     = 0777\r\n09:30:01 fstat(3, {st_mode=S_IFREG, st_size=0, ...}) = 0\r\n09:30:01 fchmod(3, 0100644)             = 0\r\n09:30:01 rename(\"/var/lib/logrotate_temp.qY37wE\", \"/var/lib/logrotate.status.tmp\") = 0\r\n09:30:01 fcntl(3, F_GETFL)              = 0x8002 (flags O_RDWR|O_LARGEFILE)\r\n09:30:01 fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0\r\n09:30:01 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f82e27cf000\r\n09:30:01 lseek(3, 0, SEEK_CUR)          = 0\r\n09:30:01 fsync(3)                       = 0\r\n09:30:01 write(3, \"logrotate state -- version 2\\n\\\"/v\"..., 928) = 928\r\n09:30:01 close(3)                       = 0\r\n09:30:01 munmap(0x7f82e27cf000, 4096)   = 0\r\n09:30:01 rename(\"/var/lib/logrotate.status.tmp\", \"/var/lib/logrotate.status\") = 0\r\n09:30:01 exit_group(0)                  = ?\r\n such file or directory)\r\n09:30:01 unlink(\"/var/lib/logrotate.status.tmp\") = -1 ENOENT (No such file or directory)\r\n09:30:01 write(2, \"error: \", 7)         = 7\r\n09:30:01 write(2, \"error renaming temp state file /\"..., 61) = 61\r\n09:30:01 exit_group(1)\r\n```\r\n#### Working Run...?\r\n```\r\nstat(\"/var/lib/logrotate.status\", {st_mode=S_IFREG|0644, st_size=928, ...}) = 0\r\n10:15:01 open(\"/var/lib/logrotate.status\", O_RDONLY) = 3\r\n10:15:01 fstat(3, {st_mode=S_IFREG|0644, st_size=928, ...}) = 0\r\n10:15:01 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f596fa47000\r\n10:15:01 read(3, \"logrotate state -- version 2\\n\\\"/v\"..., 4096) = 928\r\n...\r\n...\r\n10:15:01 unlink(\"/var/lib/logrotate.status.tmp\") = -1 ENOENT (No such file or directory)\r\n10:15:01 open(\"/var/lib/logrotate.status\", O_RDONLY) = 3\r\n10:15:01 fgetxattr(3, \"system.posix_acl_access\", 0x7fff90171390, 132) = -1 EOPNOTSUPP (Operation not supported)\r\n10:15:01 close(3)                       = 0\r\n10:15:01 stat(\"/var/lib/logrotate.status\", {st_mode=S_IFREG|0644, st_size=928, ...}) = 0\r\n10:15:01 umask(0777)                    = 022\r\n10:15:01 getpid()                       = 8010\r\n10:15:01 open(\"/var/lib/logrotate_temp.vWdK6Y\", O_RDWR|O_CREAT|O_EXCL, 0600) = 3\r\n10:15:01 umask(022)                     = 0777\r\n10:15:01 fstat(3, {st_mode=S_IFREG, st_size=0, ...}) = 0\r\n10:15:01 fchmod(3, 0100644)             = 0\r\n10:15:01 rename(\"/var/lib/logrotate_temp.vWdK6Y\", \"/var/lib/logrotate.status.tmp\") = 0\r\n10:15:01 fcntl(3, F_GETFL)              = 0x8002 (flags O_RDWR|O_LARGEFILE)\r\n10:15:01 fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0\r\n10:15:01 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f596fa47000\r\n10:15:01 lseek(3, 0, SEEK_CUR)          = 0\r\n10:15:01 fsync(3)                       = 0\r\n10:15:01 write(3, \"logrotate state -- version 2\\n\\\"/v\"..., 928) = 928\r\n10:15:01 close(3)                       = 0\r\n10:15:01 munmap(0x7f596fa47000, 4096)   = 0\r\n10:15:01 rename(\"/var/lib/logrotate.status.tmp\", \"/var/lib/logrotate.status\") = 0\r\n10:15:01 exit_group(0)                  = ?\r\n```\r\nWhen we look at the error run, We have an \"fgetxattr\" system call that throws a EOPNOTSUPP (operation not supported on socket). Not sure if this is meaningful to the error. \r\nThen we can see that during the unlink() function is where we get the error for the logrotate.status.tmp with an ENOENT (which is No such file or directory). This makes sense because there are two rename() function calls: \r\n`rename(\"/var/lib/logrotate_temp.qY37wE\", \"/var/lib/logrotate.status.tmp\")`\r\nand then \r\n`rename(\"/var/lib/logrotate.status.tmp\", \"/var/lib/logrotate.status\") = 0`. \r\nThis would mean when the unlink runs, there is no longer a file named \"logrotate.status.tmp\". Why this happens and in this order, I have no idea since /usr/sbin/logrotate is a binary.\r\n\r\n## Thoughts?\r\nAny ideas or anything else I can do or try?\r\nIs there any more information I can provide that would be helpful to look into this problem?"},"comment":{"url":"https://api.github.com/repos/logrotate/logrotate/issues/comments/389477458","html_url":"https://github.com/logrotate/logrotate/issues/197#issuecomment-389477458","issue_url":"https://api.github.com/repos/logrotate/logrotate/issues/197","id":389477458,"user":{"login":"kdudka","id":227483,"avatar_url":"https://avatars3.githubusercontent.com/u/227483?v=4","gravatar_id":"","url":"https://api.github.com/users/kdudka","html_url":"https://github.com/kdudka","followers_url":"https://api.github.com/users/kdudka/followers","following_url":"https://api.github.com/users/kdudka/following{/other_user}","gists_url":"https://api.github.com/users/kdudka/gists{/gist_id}","starred_url":"https://api.github.com/users/kdudka/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/kdudka/subscriptions","organizations_url":"https://api.github.com/users/kdudka/orgs","repos_url":"https://api.github.com/users/kdudka/repos","events_url":"https://api.github.com/users/kdudka/events{/privacy}","received_events_url":"https://api.github.com/users/kdudka/received_events","type":"User","site_admin":false},"created_at":"2018-05-16T10:51:54Z","updated_at":"2018-05-16T10:51:54Z","author_association":"MEMBER","body":"Thanks!  Unfortunately, the ltrace output above does not capture the problematic `unlink()` call, so it cannot explain why it happens."}}
{"actor":{"display_login":"kdudka"}}