These warnings appear a few times daily, and are sometimes followed by: warning: disabling connection caching
This occurs on a slightly older Postfix (2.7.1). The machine receives mail from the internet and relays everything (that it does not reject) to an internal mail store which is listed as relayhost. I have not included 'postconf -n', but please let me know if it would help debug the problem. I've included some (slightly obfuscated) log snippets below. I fully appreciate that crystal balls do not exist, so let me know if I should include more logging; I would like to avoid uploading the whole thing, but also do not want to waste people's time with snippets if they are insufficient. All cache-related variables are at their default; i.e. on-demand caching kicks in as designed, and smtp_connection_cache_destinations is empty. Again, for this machine, there is always only one destination: the relayhost. Right now, this is just an optical nuisance; these warnings are not followed by fatal errors or panics, and mail continues to flow to the internal IMAP store that also runs Postfix (an ancient version that I am embarassed to even disclose). And it is not as if on-demand caching is forever disabled; it appears to kick back in every now and then (as evidenced by the conn_use logging throughout the logs). But I am just curious since I've never seen this before on any of my other mail servers. The 'Operation timed out' warnings seem to be logged ~5s after the last successful delivery by an associated smtp(8) instance, so I guess that is connection_cache_protocol_timeout or mere coincidence. Before I try to debug further, I just wonder if any of you have seen this and could push me in the right direction. I did do a quick scan of the archives, but could not find an analogous posting. ... Dec 14 02:00:13 mx0 postfix/smtp[52172]: 82A9D8FC0A: to=<r...@example.org>, relay=internal.example.org[ip_address]:25, delay=1.8, delays=0.66/0/0/1.1, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 47E9B1065670) Dec 14 02:00:18 mx0 postfix/smtp[52172]: warning: problem talking to service private/scache: Operation timed out Dec 14 02:00:25 mx0 postfix/smtp[52172]: warning: problem talking to service private/scache: Operation timed out Dec 14 02:00:25 mx0 postfix/smtp[52172]: warning: disabling connection caching Dec 14 02:00:25 mx0 postfix/smtp[52172]: 66F498FC12: to=<d...@example.org>, relay=internal.example.org[ip_address]:25, delay=13, delays=0.29/0.6/12/0.16, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 3E6511065675) ... Dec 14 02:50:03 mx0 postfix/smtp[52897]: D4C548FC14: to=<t...@example.org>, relay=internal.example.org[ip_address]:25, delay=1.9, delays=1.9/0/0/0.04, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as E08E71065672) Dec 14 02:50:09 mx0 postfix/smtp[52897]: warning: problem talking to service private/scache: Operation timed out Dec 14 02:50:12 mx0 postfix/smtp[52897]: D4C0A8FC13: to=<t...@example.org>, relay=internal.example.org[ip_address]:25, delay=10, delays=1.9/0.04/8.2/0, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 25E4F1065673) Dec 14 02:50:12 mx0 postfix/smtp[52897]: D8A148FC16: to=<s...@example.org>, relay=internal.example.org[ip_address]:25, conn_use=2, delay=10, delays=1.9/8.3/0/0, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 279EC1065678) Dec 14 02:50:14 mx0 postfix/smtp[52897]: 880FA8FC0A: to=<br...@example.org>, relay=internal.example.org[ip_address]:25, delay=0.74, delays=0.63/0/0/0.1, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as D13AD106564A) ... Dec 14 02:50:03 mx0 postfix/smtp[52902]: D4B7A8FC0C: to=<sc...@example.org>, relay=internal.example.org[ip_address]:25, delay=1.9, delays=1.9/0/0/0.05, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as E391B1065673) Dec 14 02:50:09 mx0 postfix/smtp[52902]: warning: problem talking to service private/scache: Operation timed out Dec 14 02:50:12 mx0 postfix/smtp[52902]: D4CB48FC15: to=<ste...@example.org>, relay=internal.example.org[ip_address]:25, delay=10, delays=1.9/0.05/8.2/0, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 25DCD1065670) Dec 14 02:50:12 mx0 postfix/smtp[52902]: D8A9B8FC18: to=<s...@example.org>, relay=internal.example.org[ip_address]:25, conn_use=2, delay=10, delays=1.9/8.3/0/0, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 278291065677) Dec 14 02:50:12 mx0 postfix/smtp[52902]: A160D8FC08: to=<ge...@example.org>, relay=internal.example.org[ip_address]:25, conn_use=3, delay=1.9, delays=1.3/0.58/0/0, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 29048106567A) Dec 14 02:50:34 mx0 postfix/smtp[52902]: 706698FC12: to=<b...@example.org>, relay=internal.example.org[ip_address]:25, delay=0.64, delays=0.63/0/0/0, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as C5AFE1065670) ... Dec 14 03:00:02 mx0 postfix/smtp[53020]: F196E8FC15: to=<h...@example.org>, relay=internal.example.org[ip_address]:25, delay=0.53, delays=0.47/0/0/0.06, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 3F6061065673) Dec 14 03:00:07 mx0 postfix/smtp[53020]: warning: problem talking to service private/scache: Operation timed out Dec 14 03:00:14 mx0 postfix/smtp[53020]: warning: problem talking to service private/scache: Operation timed out Dec 14 03:00:14 mx0 postfix/smtp[53020]: warning: disabling connection caching Dec 14 03:00:14 mx0 postfix/smtp[53020]: F1EA38FC18: to=<m...@example.org>, relay=internal.example.org[ip_address]:25, delay=12, delays=0.46/0.05/12/0.07, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 2895F1065670) Dec 14 03:00:14 mx0 postfix/smtp[53020]: 044B48FC1A: to=<f...@example.org>, relay=internal.example.org[ip_address]:25, delay=9.5, delays=0.56/8.8/0/0.1, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 41BCD1065676) Dec 14 03:00:14 mx0 postfix/smtp[53020]: B60FD8FC14: to=<f...@example.org>, relay=internal.example.org[ip_address]:25, delay=9.9, delays=1.1/8.6/0/0.07, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 5325E1065677) ... -- Sahil Tandon
