Bug 1149518 - chronyd[593]: Could not create directory /var/log/chrony
Summary: chronyd[593]: Could not create directory /var/log/chrony
Keywords:
Status: CLOSED WORKSFORME
Alias: None
Product: Fedora
Classification: Fedora
Component: chrony
Version: 20
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Miroslav Lichvar
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-10-05 19:12 UTC by Neil
Modified: 2015-05-07 14:43 UTC (History)
2 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2015-05-07 14:43:18 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
terminal output (62.68 KB, image/png)
2014-10-05 19:12 UTC, Neil
no flags Details

Description Neil 2014-10-05 19:12:19 UTC
Just run "systemctl status chronyd.service" and saw that.

Comment 1 Neil 2014-10-05 19:12:56 UTC
Created attachment 944070 [details]
terminal output

Comment 2 Miroslav Lichvar 2014-10-06 08:29:09 UTC
The /var/log/chrony directory is included in the chrony package so that the chrony daemon doesn't need to create it. If it's missing, it will fail because it tries to create it after it drops the root privileges.

Do you know what removed the directory? Reinstalling the chrony package should fix it, or you could create it manually with

mkdir /var/log/chrony
restorecon /var/log/chrony

Comment 3 Neil 2014-10-07 19:17:25 UTC
>Do you know what removed the directory? 
Its a fresh minimal install (no DE), that's why I made this bug report.

>Reinstalling the chrony package should fix it
I did it and the bug is still present 

>mkdir /var/log/chrony
(I didn't noticed that it was already created, pretty weird hum?)
>restorecon /var/log/chrony
that hit the spot, its fixed


Now, I tried to if chrony was working alright, but, when I run chronyc and type timertc says "506 Cannot talk to daemon", what does that mean?

Comment 4 Miroslav Lichvar 2014-10-08 08:22:01 UTC
If restorecon helped, it means that chronyd wasn't allowed to access the /var/log/directory due to a bad selinux context. I'm not sure how that could happen.

When you reinstall the package again and run the following command, do you see the same output?

$ ls -dZ /var/log/chrony
drwxr-xr-x. chrony chrony system_u:object_r:chronyd_var_log_t:s0 /var/log/chrony

As for the "506 Cannot talk to daemon" error, that means chronyc is not able to connect to chronyd. Is the service running? Are you using the default chrony.conf?

Comment 5 Neil 2014-10-08 20:28:11 UTC
(In reply to Miroslav Lichvar from comment #4)
> If restorecon helped, it means that chronyd wasn't allowed to access the
> /var/log/directory due to a bad selinux context. I'm not sure how that could
> happen.
> 
> When you reinstall the package again and run the following command, do you
> see the same output?
> 
> $ ls -dZ /var/log/chrony
> drwxr-xr-x. chrony chrony system_u:object_r:chronyd_var_log_t:s0
> /var/log/chrony

Yup, its the same, mmm, do you know if SELinux "reload" their context automatically before update? On a fresh Fedora 20 install (not updated, default packages) its really easy to have bugs like this with Chrony and Audit (SELinux don't allow to access to their respective /var/log/* and /etc/* directory), I'm running an updated Fedora 20, and I had almost the same bug with audit (SELinux don't allow audit to access) and I fixed it like I did it with chrony.
 
> As for the "506 Cannot talk to daemon" error, that means chronyc is not able
> to connect to chronyd. Is the service running? Are you using the default
> chrony.conf?

Yes, is running, and I'm using the default chrony.conf

Comment 6 Miroslav Lichvar 2014-10-09 14:07:13 UTC
(In reply to Duff Padmasana from comment #5)
> (In reply to Miroslav Lichvar from comment #4)
> > $ ls -dZ /var/log/chrony
> > drwxr-xr-x. chrony chrony system_u:object_r:chronyd_var_log_t:s0
> > /var/log/chrony
> 
> Yup, its the same, mmm, do you know if SELinux "reload" their context
> automatically before update?

The policy is reloaded in the kernel when the package is updated, but I don't think it relabels the filesystem. If some context is wrong, restorecon is needed to fix it.

So, you are getting the same ls -dZ output and it still complains it can't create the directory? Maybe the permission are wrong?

$ ls -ld /var/log/chrony
drwxr-xr-x. 2 chrony chrony 4096 Oct  6 03:34 /var/log/chrony

> > As for the "506 Cannot talk to daemon" error, that means chronyc is not able
> > to connect to chronyd. Is the service running? Are you using the default
> > chrony.conf?
> 
> Yes, is running, and I'm using the default chrony.conf

That's odd. What does "netstat -a -n -p | grep chronyd" print? Is it listening on port 323?

Comment 7 Neil 2014-10-09 18:32:53 UTC
(In reply to Miroslav Lichvar from comment #6)

> The policy is reloaded in the kernel when the package is updated, but I
> don't think it relabels the filesystem. If some context is wrong, restorecon
> is needed to fix it.
> 
> So, you are getting the same ls -dZ output and it still complains it can't
> create the directory? Maybe the permission are wrong?
> 
> $ ls -ld /var/log/chrony
> drwxr-xr-x. 2 chrony chrony 4096 Oct  6 03:34 /var/log/chrony

$ ls -ld /var/log/chrony
drwxr-xr-x. 1 chrony chrony 0 ago 15 07:17 /var/log/chrony

That's my output.


> That's odd. What does "netstat -a -n -p | grep chronyd" print? Is it
> listening on port 323?

$ netstat -a -n -p | grep chronyd
udp        0      0 0.0.0.0:123             0.0.0.0:*                           597/chronyd         
udp        0      0 127.0.0.1:323           0.0.0.0:*                           597/chronyd         
udp6       0      0 :::123                  :::*                                597/chronyd         
udp6       0      0 ::1:323                 :::*                                597/chronyd         
unix  2      [ ]         DGRAM                    17268    597/chronyd

Comment 8 Miroslav Lichvar 2014-10-10 05:50:07 UTC
(In reply to Duff Padmasana from comment #7)
> $ ls -ld /var/log/chrony
> drwxr-xr-x. 1 chrony chrony 0 ago 15 07:17 /var/log/chrony
> 
> That's my output.

I'm not sure what's wrong then.

> $ netstat -a -n -p | grep chronyd
> udp        0      0 0.0.0.0:123             0.0.0.0:*                       
> 597/chronyd         
> udp        0      0 127.0.0.1:323           0.0.0.0:*                       

Hm, that looks ok. Can you please try running chronyc in strace (e.g. "strace chronyc tracking") and see if it's actually sending packets to chronyd?

Comment 9 Neil 2014-10-11 07:33:43 UTC
$ strace chronyc tracking
execve("/bin/chronyc", ["chronyc", "tracking"], [/* 39 vars */]) = 0
brk(0)                                  = 0x7ff3c16fe000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ff3c0db8000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=132021, ...}) = 0
mmap(NULL, 132021, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7ff3c0d97000
close(3)                                = 0
open("/lib64/libm.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\220X\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1159944, ...}) = 0
mmap(NULL, 3170648, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7ff3c0893000
mprotect(0x7ff3c0998000, 2097152, PROT_NONE) = 0
mmap(0x7ff3c0b98000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x105000) = 0x7ff3c0b98000
close(3)                                = 0
open("/lib64/libfreebl3.so", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\200?\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=502096, ...}) = 0
mmap(NULL, 2606920, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7ff3c0616000
mprotect(0x7ff3c068d000, 2093056, PROT_NONE) = 0
mmap(0x7ff3c088c000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x76000) = 0x7ff3c088c000
mmap(0x7ff3c088f000, 14152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7ff3c088f000
close(3)                                = 0
open("/lib64/libedit.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\320\315`\244;\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=230152, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ff3c0d96000
mmap(NULL, 2340448, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7ff3c03da000
mprotect(0x7ff3c040f000, 2093056, PROT_NONE) = 0
mmap(0x7ff3c060e000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x34000) = 0x7ff3c060e000
mmap(0x7ff3c0611000, 18016, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7ff3c0611000
close(3)                                = 0
open("/lib64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\220m\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=147496, ...}) = 0
mmap(NULL, 2213104, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7ff3c01bd000
mprotect(0x7ff3c01d5000, 2093056, PROT_NONE) = 0
mmap(0x7ff3c03d4000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x17000) = 0x7ff3c03d4000
mmap(0x7ff3c03d6000, 13552, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7ff3c03d6000
close(3)                                = 0
open("/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0p\36\2\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=2093096, ...}) = 0
mmap(NULL, 3920480, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7ff3bfdff000
mprotect(0x7ff3bffb3000, 2093056, PROT_NONE) = 0
mmap(0x7ff3c01b2000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b3000) = 0x7ff3c01b2000
mmap(0x7ff3c01b8000, 16992, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7ff3c01b8000
close(3)                                = 0
open("/lib64/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\320\16\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=19512, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ff3c0d95000
mmap(NULL, 2109744, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7ff3bfbfb000
mprotect(0x7ff3bfbfe000, 2093056, PROT_NONE) = 0
mmap(0x7ff3bfdfd000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7ff3bfdfd000
close(3)                                = 0
open("/lib64/libtinfo.so.5", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0@\316 \265;\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=175560, ...}) = 0
mmap(NULL, 2268928, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7ff3bf9d1000
mprotect(0x7ff3bf9f6000, 2097152, PROT_NONE) = 0
mmap(0x7ff3bfbf6000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x25000) = 0x7ff3bfbf6000
close(3)                                = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ff3c0d94000
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ff3c0d92000
arch_prctl(ARCH_SET_FS, 0x7ff3c0d92740) = 0
mprotect(0x7ff3c01b2000, 16384, PROT_READ) = 0
mprotect(0x7ff3bfbf6000, 16384, PROT_READ) = 0
mprotect(0x7ff3bfdfd000, 4096, PROT_READ) = 0
mprotect(0x7ff3c03d4000, 4096, PROT_READ) = 0
mprotect(0x7ff3c060e000, 8192, PROT_READ) = 0
mprotect(0x7ff3c088c000, 8192, PROT_READ) = 0
mprotect(0x7ff3c0b98000, 4096, PROT_READ) = 0
mprotect(0x7ff3c0fcb000, 4096, PROT_READ) = 0
mprotect(0x7ff3c0db9000, 4096, PROT_READ) = 0
munmap(0x7ff3c0d97000, 132021)          = 0
set_tid_address(0x7ff3c0d92a10)         = 9656
set_robust_list(0x7ff3c0d92a20, 24)     = 0
rt_sigaction(SIGRTMIN, {0x7ff3c01c3880, [], SA_RESTORER|SA_SIGINFO, 0x7ff3c01cc6d0}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {0x7ff3c01c3910, [], SA_RESTORER|SA_RESTART|SA_SIGINFO, 0x7ff3c01cc6d0}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
ioctl(0, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
ioctl(1, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
ioctl(2, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
futex(0x7ff3bfdfe0d0, FUTEX_WAKE_PRIVATE, 2147483647) = 0
brk(0)                                  = 0x7ff3c16fe000
brk(0x7ff3c171f000)                     = 0x7ff3c171f000
brk(0)                                  = 0x7ff3c171f000
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=132021, ...}) = 0
mmap(NULL, 132021, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7ff3c0d97000
close(3)                                = 0
open("/lib64/libnspr4.so", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\340\321\340\263;\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=251568, ...}) = 0
close(3)                                = 0
munmap(0x7ff3c0d97000, 132021)          = 0
open("/proc/sys/crypto/fips_enabled", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ff3c0db7000
read(3, "0\n", 1024)                    = 2
close(3)                                = 0
munmap(0x7ff3c0db7000, 4096)            = 0
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 3
setsockopt(3, SOL_IP, IP_RECVERR, [1], 4) = 0
sendto(3, "\6\1\0\0\0!\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 120, 0, {sa_family=AF_INET, sin_port=htons(323), sin_addr=inet_addr("127.0.0.1")}, 16) = 120
select(4, [3], [], [], {0, 100000})     = 0 (Timeout)
sendto(3, "\6\1\0\0\0!\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 120, 0, {sa_family=AF_INET, sin_port=htons(323), sin_addr=inet_addr("127.0.0.1")}, 16) = 120
select(4, [3], [], [], {0, 200000})     = 0 (Timeout)
sendto(3, "\6\1\0\0\0!\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 120, 0, {sa_family=AF_INET, sin_port=htons(323), sin_addr=inet_addr("127.0.0.1")}, 16) = 120
select(4, [3], [], [], {0, 400000})     = 0 (Timeout)
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ff3c0db7000
write(1, "506 Cannot talk to daemon\n", 26506 Cannot talk to daemon
) = 26
close(3)                                = 0
exit_group(1)                           = ?
+++ exited with 1 +++

Comment 10 Miroslav Lichvar 2014-10-13 08:01:42 UTC
Ok, so chronyc is sending packets, but is not getting any response. I guess this could be a firewall issue.

Do you have masquerading enabled in firewalld? Or any custom rules?

Comment 11 Neil 2014-10-14 08:24:07 UTC
Yep, I had masquerading enabled, can't remember why, thanks, now it works fine.

Comment 12 Neil 2014-10-14 08:29:02 UTC
But, I don't know why my /var/log/chrony got deleted, so I 
>mkdir /var/log/chrony
>restorecon /var/log/chrony
again and it works fine, looks like SELinux and Systemd are some serious coctel.

Comment 13 Miroslav Lichvar 2014-10-14 08:37:49 UTC
(In reply to Duff Padmasana from comment #11)
> Yep, I had masquerading enabled, can't remember why, thanks, now it works
> fine.

Ok, that means chronyd doesn't see the incoming packets as from 127.0.0.1, but an address that is not allowed by the cmdallow directive in /etc/chrony.conf.

Can you please file a new bug for firewalld? It looks similar to 
bug #904098, but that one is already closed.

As for the problem with missing /var/log/chrony, I'm still not sure how that can happen.

Comment 14 Miroslav Lichvar 2015-05-07 14:43:18 UTC
I'm closing this. Please reopen if it happens again.


Note You need to log in before you can comment on or make changes to this bug.