Zimbra 7.1.1_GA-zmconfigd ERROR 14116-postconf

Ask questions about your setup or get help installing ZCS server (ZD section below).
HenningMalzahn
Posts: 12
Joined: Sat Sep 13, 2014 2:04 am

Zimbra 7.1.1_GA-zmconfigd ERROR 14116-postconf

Postby HenningMalzahn » Wed Jun 15, 2011 4:43 am

Hello Forum,
some system facts first:

- Ubuntu 10.04 LTS,

- Virtual Machine, Running on ESXi 4.1

- 64 Bit

- 3328 MB RAM

- 4 Processors assigned

- Zimbra 7.1.1_GA_3196.UBUNTU10_64 UBUNTU10_64 FOSS edition
Successful installation without any issues. Changed the following during the installation

- Alternative HTTP port as there is an existing Apache2 on the machine

- Alternative HTTPS port

- HTTPS only mode
System starts up ok but when monitoring the log file


/opt/zimbra/log/zmconfigd.log


the following does not look like it should be that way


...

2011-06-15 11:23:47,967 zmconfigd CRITICAL [19186-rewrites] File "/opt/zimbra/zimbramon/pylibs/state.py", line 683, in rewriteConfig os.unlink(to)

2011-06-15 11:23:47,969 zmconfigd CRITICAL [19186-rewrites] File "/opt/zimbra/lib/jars/jython-2.5.1.jar/Lib/os.py", line 342, in remove raise OSError(0, "couldn't delete file", path)

2011-06-15 11:23:47,970 zmconfigd CRITICAL [19186-rewrites] Rewrite failed: [Errno 0] couldn't delete file: '/opt/zimbra/postfix/conf/master.cf' ([Errno 0] couldn't delete file: '/opt/zimbra/postfix/conf/master.cf')

...

2011-06-15 11:23:48,444 zmconfigd WARNING [19186-rewrites] Rewrote: /opt/zimbra/conf/amavisd.conf with mode 440 (0.08 sec)

2011-06-15 11:23:48,460 zmconfigd WARNING [19186-rewrites] Rewrote: /opt/zimbra/conf/salocal.cf with mode 440 (0.02 sec)

2011-06-15 11:23:48,710 zmconfigd ERROR [19186-postconf] Executed: /opt/zimbra/postfix/sbin/postconf -e mail_owner='postfix' returned 1 (14 - 112) (1.07 sec)

2011-06-15 11:23:49,732 zmconfigd ERROR [19186-postconf] Executed: /opt/zimbra/postfix/sbin/postconf -e bounce_notice_recipient='postmaster' returned 1 (14 - 112) (1.02 sec)

2011-06-15 11:23:50,746 zmconfigd ERROR [19186-postconf] Executed: /opt/zimbra/postfix/sbin/postconf -e content_filter='smtp-amavis:[127.0.0.1]:10024' returned 1 (14 - 112) (1.01 sec)

2011-06-15 11:23:51,757 zmconfigd ERROR [19186-postconf] Executed: /opt/zimbra/postfix/sbin/postconf -e relayhost='' returned 1 (14 - 112) (1.01 sec)

2011-06-15 11:23:52,769 zmconfigd ERROR [19186-postconf] Executed: /opt/zimbra/postfix/sbin/postconf -e smtpd_sasl_authenticated_header='no' returned 1 (14 - 112) (1.01 sec)

2011-06-15 11:23:53,782 zmconfigd ERROR [19186-postconf] Executed: /opt/zimbra/postfix/sbin/postconf -e broken_sasl_auth_clients='yes' returned 1 (14 - 112) (1.01 sec)

2011-06-15 11:23:54,796 zmconfigd ERROR [19186-postconf] Executed: /opt/zimbra/postfix/sbin/postconf -e minimal_backoff_time='300s' returned 1 (14 - 112) (1.01 sec)


I do not want to flood this whole thread with all the error messages but it looks like every postconf command failing. When leaving the system up and running for a while the following is logged repeatedly


2011-06-15 11:25:47,813 zmconfigd CRITICAL [19186-rewrites] File "/opt/zimbra/zimbramon/pylibs/state.py", line 683, in rewriteConfig os.unlink(to)

2011-06-15 11:25:47,815 zmconfigd CRITICAL [19186-rewrites] File "/opt/zimbra/lib/jars/jython-2.5.1.jar/Lib/os.py", line 342, in remove raise OSError(0, "couldn't delete file", path)

2011-06-15 11:25:47,816 zmconfigd CRITICAL [19186-rewrites] Rewrite failed: [Errno 0] couldn't delete file: '/opt/zimbra/postfix/conf/master.cf' ([Errno 0] couldn't delete file: '/opt/zimbra/postfix/conf/master.cf')

2011-06-15 11:25:47,818 zmconfigd WARNING [19186-MainThread] All rewrite threads completed in 0.01 sec

2011-06-15 11:25:47,819 zmconfigd WARNING [19186-MainThread] All restarts completed in 0.00 sec

2011-06-15 11:26:47,832 zmconfigd WARNING [19186-MainThread] Fetching All configs

2011-06-15 11:26:48,131 zmconfigd WARNING [19186-MainThread] All configs fetched in 0.30 seconds

2011-06-15 11:26:49,033 zmconfigd WARNING [19186-MainThread] Watchdog: service antivirus status is OK.

2011-06-15 11:26:49,190 zmconfigd CRITICAL [19186-rewrites] File "/opt/zimbra/zimbramon/pylibs/state.py", line 683, in rewriteConfig os.unlink(to)

2011-06-15 11:26:49,190 zmconfigd CRITICAL [19186-rewrites] File "/opt/zimbra/lib/jars/jython-2.5.1.jar/Lib/os.py", line 342, in remove raise OSError(0, "couldn't delete file", path)

2011-06-15 11:26:49,191 zmconfigd CRITICAL [19186-rewrites] Rewrite failed: [Errno 0] couldn't delete file: '/opt/zimbra/postfix/conf/master.cf' ([Errno 0] couldn't delete file: '/opt/zimbra/postfix/conf/master.cf')


When shutting down Zimbra using the regular command



service zimbra stop


a stack trace of the Java VM with the following content is created on every shutdown



zmthrdump: Requested thread dump [PID 16142] at Wed Jun 15 11:22:44 2011

Full thread dump Java HotSpot(TM) 64-Bit Server VM (20.0-b11 mixed mode):
"DestroyJavaVM" prio=10 tid=0x00007fa5dc1f6800 nid=0x3f1b waiting on condition [0x0000000000000000]

java.lang.Thread.State: RUNNABLE
....
"pool-2-thread-1" prio=10 tid=0x00007fa5e4c04800 nid=0x3fbf runnable [0x00007fa5e246f000]

java.lang.Thread.State: RUNNABLE

at java.net.PlainSocketImpl.socketAccept(Native Method)

at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:408)

- locked (a java.net.SocksSocketImpl)

at java.net.ServerSocket.implAccept(ServerSocket.java:462)

at java.net.ServerSocket.accept(ServerSocket.java:430)

at org.jivesoftware.wildfire.filetransfer.proxy.ProxyConnectionManager$1.run(ProxyConnectionManager.java:96)

at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)

at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)

at java.util.concurrent.FutureTask.run(FutureTask.java:138)

at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

at java.lang.Thread.run(Thread.java:662)
"SocketSendingTracker" daemon prio=10 tid=0x00007fa5e4cb3000 nid=0x3fbe in Object.wait() [0x00007fa5e24b0000]

java.lang.Thread.State: TIMED_WAITING (on object monitor)

at java.lang.Object.wait(Native Method)

- waiting on (a org.jivesoftware.wildfire.net.SocketSendingTracker$1)

at org.jivesoftware.wildfire.net.SocketSendingTracker$1.run(SocketSendingTracker.java:78)

- locked (a org.jivesoftware.wildfire.net.SocketSendingTracker$1)
"Secure Socket Listener" daemon prio=10 tid=0x00007fa5e4d3a800 nid=0x3fbd runnable [0x00007fa5e24f1000]

java.lang.Thread.State: RUNNABLE

at java.net.PlainSocketImpl.socketAccept(Native Method)

at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:408)

- locked (a java.net.SocksSocketImpl)

at java.net.ServerSocket.implAccept(ServerSocket.java:462)

at com.sun.net.ssl.internal.ssl.SSLServerSocketImpl.accept(SSLServerSocketImpl.java:261)

at org.jivesoftware.wildfire.net.SSLSocketAcceptThread.run(SSLSocketAcceptThread.java:148)
"Secure Socket Listener" daemon prio=10 tid=0x00007fa5e4144800 nid=0x3fb9 runnable [0x00007fa5e25f5000]

java.lang.Thread.State: RUNNABLE

at java.net.PlainSocketImpl.socketAccept(Native Method)

at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:408)

- locked (a java.net.SocksSocketImpl)

at java.net.ServerSocket.implAccept(ServerSocket.java:462)

at com.sun.net.ssl.internal.ssl.SSLServerSocketImpl.accept(SSLServerSocketImpl.java:261)

at org.jivesoftware.wildfire.net.SSLSocketAcceptThread.run(SSLSocketAcceptThread.java:148)
"Auditor" prio=10 tid=0x00007fa5e4799000 nid=0x3fb8 in Object.wait() [0x00007fa5e2636000]

java.lang.Thread.State: TIMED_WAITING (on object monitor)

at java.lang.Object.wait(Native Method)

- waiting on (a java.util.TaskQueue)

at java.util.TimerThread.mainLoop(Timer.java:509)

- locked (a java.util.TaskQueue)

at java.util.TimerThread.run(Timer.java:462)
"MUC cleanup" prio=10 tid=0x00007fa5e4596800 nid=0x3fb7 in Object.wait() [0x00007fa5e2677000]

java.lang.Thread.State: TIMED_WAITING (on object monitor)

at java.lang.Object.wait(Native Method)

- waiting on (a java.util.TaskQueue)

at java.util.TimerThread.mainLoop(Timer.java:509)

- locked (a java.util.TaskQueue)

at java.util.TimerThread.run(Timer.java:462)
"Sessions cleanup" prio=10 tid=0x00007fa5e4c19000 nid=0x3fb4 in Object.wait() [0x00007fa5e26b8000]

java.lang.Thread.State: TIMED_WAITING (on object monitor)

at java.lang.Object.wait(Native Method)

- waiting on (a java.util.TaskQueue)

at java.util.TimerThread.mainLoop(Timer.java:509)

- locked (a java.util.TaskQueue)

at java.util.TimerThread.run(Timer.java:462)
"PooledByteBufferExpirer-0" daemon prio=10 tid=0x00007fa5e41bf800 nid=0x3fb2 waiting on condition [0x00007fa5e26f9000]

java.lang.Thread.State: TIMED_WAITING (sleeping)

at java.lang.Thread.sleep(Native Method)

at org.apache.mina.common.PooledByteBufferAllocator$Expirer.run(PooledByteBufferAllocator.java:249)
"FileLogWriter.FsyncThread" prio=10 tid=0x00007fa5e4d0b000 nid=0x3fb1 waiting on condition [0x00007fa5e273a000]

java.lang.Thread.State: TIMED_WAITING (sleeping)

at java.lang.Thread.sleep(Native Method)

at com.zimbra.cs.redolog.logger.FileLogWriter$FsyncThread.run(FileLogWriter.java:521)
....
"btpool0-5 - Acceptor1 SslSelectChannelConnector@0.0.0.0:7071" prio=10 tid=0x00007fa5e4211000 nid=0x3f4a runnable [0x00007fa5e89af000]

java.lang.Thread.State: RUNNABLE

at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)

at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:210)

at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:65)

at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)

- locked (a sun.nio.ch.Util$2)

- locked (a java.util.Collections$UnmodifiableSet)

- locked (a sun.nio.ch.EPollSelectorImpl)

at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)

at org.mortbay.io.nio.SelectorManager$SelectSet.doSelect(SelectorManager.java:498)

at org.mortbay.io.nio.SelectorManager.doSelect(SelectorManager.java:192)

at org.mortbay.jetty.nio.SelectChannelConnector.accept(SelectChannelConnector.java:124)

at org.mortbay.jetty.AbstractConnector$Acceptor.run(AbstractConnector.java:708)

at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:451)
"btpool0-4 - Acceptor0 SslSelectChannelConnector@0.0.0.0:7071" prio=10 tid=0x00007fa5e41fc800 nid=0x3f49 runnable [0x00007fa5e89f0000]

java.lang.Thread.State: RUNNABLE

at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)

at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:210)

at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:65)

at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)

- locked (a sun.nio.ch.Util$2)

- locked (a java.util.Collections$UnmodifiableSet)

- locked (a sun.nio.ch.EPollSelectorImpl)

at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)

at org.mortbay.io.nio.SelectorManager$SelectSet.doSelect(SelectorManager.java:498)

at org.mortbay.io.nio.SelectorManager.doSelect(SelectorManager.java:192)

at org.mortbay.jetty.nio.SelectChannelConnector.accept(SelectChannelConnector.java:124)

at org.mortbay.jetty.AbstractConnector$Acceptor.run(AbstractConnector.java:708)

at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:451)
....
"Low Memory Detector" daemon prio=10 tid=0x00007fa5e4001800 nid=0x3f37 runnable [0x0000000000000000]

java.lang.Thread.State: RUNNABLE
"C2 CompilerThread1" daemon prio=10 tid=0x00000000416cc800 nid=0x3f36 waiting on condition [0x0000000000000000]

java.lang.Thread.State: RUNNABLE
"C2 CompilerThread0" daemon prio=10 tid=0x00000000416ca000 nid=0x3f35 waiting on condition [0x0000000000000000]

java.lang.Thread.State: RUNNABLE
"Signal Dispatcher" daemon prio=10 tid=0x00000000416c7800 nid=0x3f34 waiting on condition [0x0000000000000000]

java.lang.Thread.State: RUNNABLE
"Surrogate Locker Thread (Concurrent GC)" daemon prio=10 tid=0x00000000416c5800 nid=0x3f33 waiting on condition [0x0000000000000000]

java.lang.Thread.State: RUNNABLE
"Finalizer" daemon prio=10 tid=0x00000000416aa000 nid=0x3f32 in Object.wait() [0x00007fa5e96d9000]

java.lang.Thread.State: WAITING (on object monitor)

at java.lang.Object.wait(Native Method)

- waiting on (a java.lang.ref.ReferenceQueue$Lock)

at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)

- locked (a java.lang.ref.ReferenceQueue$Lock)

at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)

at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)
"Reference Handler" daemon prio=10 tid=0x00000000416a2800 nid=0x3f31 in Object.wait() [0x00007fa5e971a000]

java.lang.Thread.State: WAITING (on object monitor)

at java.lang.Object.wait(Native Method)

- waiting on (a java.lang.ref.Reference$Lock)

at java.lang.Object.wait(Object.java:485)

at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)

- locked (a java.lang.ref.Reference$Lock)
"VM Thread" prio=10 tid=0x000000004169c000 nid=0x3f30 runnable
"Gang worker#0 (Parallel GC Threads)" prio=10 tid=0x0000000041528000 nid=0x3f20 runnable
"Gang worker#1 (Parallel GC Threads)" prio=10 tid=0x000000004152a000 nid=0x3f21 runnable
"Gang worker#2 (Parallel GC Threads)" prio=10 tid=0x000000004152c000 nid=0x3f22 runnable
"Gang worker#3 (Parallel GC Threads)" prio=10 tid=0x000000004152d800 nid=0x3f23 runnable
"Concurrent Mark-Sweep GC Thread" prio=10 tid=0x00000000415bd000 nid=0x3f2b runnable

"VM Periodic Task Thread" prio=10 tid=0x00007fa5e400d000 nid=0x3f38 waiting on condition



(Needed to shorten the stack trace - otherwise the text was to long to post)
The same happens when the system is just left running for a while (Installed yesterday so I can't really say anything yet about the periods, Looks like it happens after 6 - 8 hours). Anyhow checking the status of Zimbra after a while using the command



service zimbra status


shows the following



Unable to determine enabled services from ldap.

Enabled services read from cache. Service list may be inaccurate.

Host

antispam Stopped

zmamavisdctl is not running

antivirus Stopped

zmamavisdctl is not running

zmclamdctl is not running

ldap Stopped

logger Stopped

zmlogswatchctl is not running

mailbox Stopped

mysql.server is not running.

zmmailboxdctl is not running.

mta Stopped

postfix is not running

zmsaslauthdctl is not running

snmp Stopped

zmswatch is not running.

spell Stopped

zmapachectl is not running

stats Stopped

zmconfigd Stopped

zmconfigd is not running.


As said above once this happened one can also find a new Java VM stack trace in the log directory.
Even though the installation completed without any issues all of the above does not look so good. Does anybody have an idea of what is going on? Any help would be greatly appreciated.
Thanks in advance.
Sincerely
Henning Malzahn


sergioag
Posts: 33
Joined: Fri Sep 12, 2014 11:13 pm

Zimbra 7.1.1_GA-zmconfigd ERROR 14116-postconf

Postby sergioag » Wed Jun 15, 2011 11:52 am

You appear to have more than one problem, but the only one I seem to understand from your post is that the /opt/zimbra/postfix/conf/master.cf file is probably owned by root. It should be owned by user zimbra and group zimbra.
Best regards,
Sergio Aguayo
HenningMalzahn
Posts: 12
Joined: Sat Sep 13, 2014 2:04 am

Zimbra 7.1.1_GA-zmconfigd ERROR 14116-postconf

Postby HenningMalzahn » Wed Jun 15, 2011 12:00 pm

Hi Sergio,
nope - that is not the problem


ls -la /opt/zimbra/postfix/conf/
drwxrwxr-x 2 root postfix 4096 2011-06-15 18:53 .

drwxr-xr-x 6 root root 4096 2011-06-15 16:10 ..

-rw-r--r-- 1 root postfix 20695 2011-05-09 23:54 access

-rw-r--r-- 1 root postfix 8829 2011-05-09 23:54 aliases

-rw-r--r-- 1 root postfix 3548 2011-05-09 23:54 bounce.cf.default

-rw-r--r-- 1 root postfix 11681 2011-05-09 23:54 canonical

-rw-r--r-- 1 root postfix 9904 2011-05-09 23:54 generic

-rw-r--r-- 1 root postfix 19310 2011-05-09 23:54 header_checks

-rw-r--r-- 1 root postfix 11942 2011-05-09 23:54 LICENSE

-rw-r--r-- 1 zimbra zimbra 2363 2011-06-15 16:25 main.cf

-rw-r--r-- 1 root postfix 24035 2011-05-09 23:54 main.cf.default

-rw-r--r-- 1 root postfix 3187 2011-05-09 23:54 makedefs.out

-rw-rw-rw- 1 zimbra zimbra 5051 2011-06-15 16:25 master.cf

-rw-r--r-- 1 zimbra zimbra 5195 2011-05-27 10:27 master.cf.in

-rw-r--r-- 1 root postfix 6816 2011-05-09 23:54 relocated

-rw-r--r-- 1 root postfix 1629 2011-05-09 23:54 TLS_LICENSE

-rw-r--r-- 1 root postfix 12549 2011-05-09 23:54 transport

-rw-r--r-- 1 root postfix 12494 2011-05-09 23:54 virtual


Trying to execute a randomly picked command that is used to attempt to write the Postfix configuration file results in


su - zimbra -c "/opt/zimbra/postfix/sbin/postconf -e message_size_limit='10240000'"

/opt/zimbra/postfix/sbin/postconf: fatal: open /opt/zimbra/postfix-2.7.4.2z/conf/main.cf.tmp: Permission denied




So long
Henning
sergioag
Posts: 33
Joined: Fri Sep 12, 2014 11:13 pm

Zimbra 7.1.1_GA-zmconfigd ERROR 14116-postconf

Postby sergioag » Wed Jun 15, 2011 12:05 pm

How are the privileges of the conf directory? They should be 775.
Best regards,
Sergio Aguayo
HenningMalzahn
Posts: 12
Joined: Sat Sep 13, 2014 2:04 am

Zimbra 7.1.1_GA-zmconfigd ERROR 14116-postconf

Postby HenningMalzahn » Wed Jun 15, 2011 12:09 pm

Hi Sergio,
thanks for your help! Here's the listing of the whole Postfix directory


ls -la /opt/zimbra/postfix/
drwxr-xr-x 6 root root 4096 2011-06-15 16:10 .

drwxr-xr-x 49 root root 4096 2011-06-15 18:02 ..

drwxrwxr-x 2 root postfix 4096 2011-06-15 18:53 conf

drwxr-xr-x 2 root root 4096 2011-06-15 16:10 libexec

drwxr-xr-x 5 root root 4096 2011-06-15 16:10 man

drwxr-xr-x 2 root root 4096 2011-06-15 16:10 sbin


Henning
sergioag
Posts: 33
Joined: Fri Sep 12, 2014 11:13 pm

Zimbra 7.1.1_GA-zmconfigd ERROR 14116-postconf

Postby sergioag » Wed Jun 15, 2011 12:14 pm

Hi Henning
I'm not very used to Ubuntu, but in CentOS/RHEL you had to disable SELinux. Maybe you have installed SELinux or another security module? This is because under "normal" unix rules this doesn't make sense...
Best regards,
Sergio Aguayo
blozancic
Posts: 21
Joined: Fri Sep 12, 2014 11:42 pm

Zimbra 7.1.1_GA-zmconfigd ERROR 14116-postconf

Postby blozancic » Wed Jun 15, 2011 12:19 pm

I'm getting the same issues with my Zimbra FOSS on Ubuntu 10.04 64 bit server. And this seemed to happen only after about we upgraded from 7.0.1 to 7.1.1.
HenningMalzahn
Posts: 12
Joined: Sat Sep 13, 2014 2:04 am

Zimbra 7.1.1_GA-zmconfigd ERROR 14116-postconf

Postby HenningMalzahn » Wed Jun 15, 2011 12:23 pm

Sergio,
Ubuntu uses Apparmor but as there is no profile for any of the Zimbra processes that should not be a problem. There's also not a single "audit" entry in syslog. This would be the case if there would be any violation of an Apparmor profile...
Henning
HenningMalzahn
Posts: 12
Joined: Sat Sep 13, 2014 2:04 am

Zimbra 7.1.1_GA-zmconfigd ERROR 14116-postconf

Postby HenningMalzahn » Wed Jun 15, 2011 12:28 pm

Hi blozancic,
do you by any change know where I could download the older version that you mention? The official download page only seems to offer the current version 7.1.1 GA.
I've just seen that there is an additional patch in that download section too. Did you try to apply that already?
Henning
HenningMalzahn
Posts: 12
Joined: Sat Sep 13, 2014 2:04 am

Zimbra 7.1.1_GA-zmconfigd ERROR 14116-postconf

Postby HenningMalzahn » Wed Jun 15, 2011 1:05 pm

Hi blozancic,
the forrest and the trees, right?

Obviously sitting a little bit too long in front of the screen today - just "found" the archives link on the download page.... :-)
Henning

Return to “Installation and Upgrade”

Who is online

Users browsing this forum: No registered users and 6 guests