Bad server.log rotation reaches filename length limits (since 365) #10394

guyco33 · 2021-12-23T11:02:23Z

The server.log file has stopped rotating correctly(daily gzip backup files) since 365.
It seems to be related to the recent airlift upgrade 200ec0e
airlift/airlift@c5adbd8
airlift/airlift@9e5ba2b

364

-rw-r--r-- 1 root root   164321 Dec 22 09:36 server.log
-rw-r--r-- 1 root root    82779 Nov 24 00:01 server.log-2021-11-23.0.log.gz
-rw-r--r-- 1 root root    53109 Nov 25 00:00 server.log-2021-11-24.0.log.gz
-rw-r--r-- 1 root root    17750 Nov 26 02:33 server.log-2021-11-25.0.log.gz
...
-rw-r--r-- 1 root root   314351 Dec 21 00:02 server.log-2021-12-20.0.log.gz
-rw-r--r-- 1 root root    18629 Dec 22 00:06 server.log-2021-12-21.0.log.gz

365+

lrwxrwxrwx 1 root root       46 Dec 20 08:15 server.log -> /data/trino/var/log/server.log-20211220.081517
lrwxrwxrwx 1 root root       62 Dec 20 09:13 server.log-20211220.081517 -> /data/trino/var/log/server.log-20211220.081517-20211220.091320
-rw-r--r-- 1 root root   643234 Dec 20 08:56 server.log-20211220.081517-20211220.085606--d8804f01-ceb6-4a14-bf35-95079913ea21
-rw-r--r-- 1 root root  4047024 Dec 22 10:34 server.log-20211220.081517-20211220.091320

The text was updated successfully, but these errors were encountered:

kokosing · 2021-12-23T11:58:26Z

cc @bitweld

bitweld · 2021-12-23T14:02:53Z

@guyco33 could You provide your log.properties content

guyco33 · 2021-12-23T14:07:47Z

log.properties

io.trino=WARN
org.eclipse.jetty.util.ssl=WARN

dain · 2021-12-23T19:47:54Z

The new logger only rolls on size. If we want to roll on some other condition, it wouldn't be too difficult to add: https://github.com/airlift/airlift/blob/729cc2fd95212d87c0343ecb1099914a2870d371/log-manager/src/main/java/io/airlift/log/RollingFileMessageOutput.java#L237-L239

guyco33 · 2021-12-26T11:51:10Z

For some reason each rotation creates a new sym link (instead of a new archived file) while the actual file name is appended with a new suffix:

-rw-r--r-- 1 root root  4683740 Dec 26 06:15 query-logger.log
lrwxrwxrwx 1 root root       46 Dec 20 10:03 server.log -> /data/trino/var/log/server.log-20211220.100347
lrwxrwxrwx 1 root root       62 Dec 20 10:27 server.log-20211220.100347 -> /data/trino/var/log/server.log-20211220.100347-20211220.102716
-rw-r--r-- 1 root root   233032 Dec 20 10:11 server.log-20211220.100347-20211220.101107--f0696e69-830f-4955-9ce1-bb4dc9513ff9
lrwxrwxrwx 1 root root       78 Dec 20 13:59 server.log-20211220.100347-20211220.102716 -> /data/trino/var/log/server.log-20211220.100347-20211220.102716-20211220.135910
-rw-r--r-- 1 root root   235724 Dec 20 13:59 server.log-20211220.100347-20211220.102716-20211220.135909--f3970518-b3ef-4473-8ad1-ab691133a5eb
lrwxrwxrwx 1 root root       94 Dec 21 06:16 server.log-20211220.100347-20211220.102716-20211220.135910 -> /data/trino/var/log/server.log-20211220.100347-20211220.102716-20211220.135910-20211221.061603
-rw-r--r-- 1 root root   235212 Dec 21 06:15 server.log-20211220.100347-20211220.102716-20211220.135910-20211221.061528--55bb76f0-2939-4f24-b0f8-72e6614b7933
lrwxrwxrwx 1 root root      110 Dec 22 11:31 server.log-20211220.100347-20211220.102716-20211220.135910-20211221.061603 -> /data/trino/var/log/server.log-20211220.100347-20211220.102716-20211220.135910-20211221.061603-20211222.113102
-rw-r--r-- 1 root root   643594 Dec 22 03:46 server.log-20211220.100347-20211220.102716-20211220.135910-20211221.061603-20211222.034624--64a47c45-473c-48b3-b74b-4151c2d00de7
lrwxrwxrwx 1 root root      126 Dec 23 15:05 server.log-20211220.100347-20211220.102716-20211220.135910-20211221.061603-20211222.113102 -> /data/trino/var/log/server.log-20211220.100347-20211220.102716-20211220.135910-20211221.061603-20211222.113102-20211223.150503
-rw-r--r-- 1 root root   272413 Dec 23 15:04 server.log-20211220.100347-20211220.102716-20211220.135910-20211221.061603-20211222.113102-20211223.150417--c39f3e81-5e6d-4080-8fce-77b08535df15
lrwxrwxrwx 1 root root      142 Dec 24 21:41 server.log-20211220.100347-20211220.102716-20211220.135910-20211221.061603-20211222.113102-20211223.150503 -> /data/trino/var/log/server.log-20211220.100347-20211220.102716-20211220.135910-20211221.061603-20211222.113102-20211223.150503-20211224.214103
-rw-r--r-- 1 root root   290039 Dec 24 21:40 server.log-20211220.100347-20211220.102716-20211220.135910-20211221.061603-20211222.113102-20211223.150503-20211224.214015--08685681-e299-4c7b-a292-a975e14c00db
lrwxrwxrwx 1 root root      158 Dec 26 00:31 server.log-20211220.100347-20211220.102716-20211220.135910-20211221.061603-20211222.113102-20211223.150503-20211224.214103 -> /data/trino/var/log/server.log-20211220.100347-20211220.102716-20211220.135910-20211221.061603-20211222.113102-20211223.150503-20211224.214103-20211226.003103
-rw-r--r-- 1 root root   664891 Dec 25 22:12 server.log-20211220.100347-20211220.102716-20211220.135910-20211221.061603-20211222.113102-20211223.150503-20211224.214103-20211225.221234--c8af8314-0cd3-4685-8275-5954b60abb94
-rw-r--r-- 1 root root   233033 Dec 26 00:32 server.log-20211220.100347-20211220.102716-20211220.135910-20211221.061603-20211222.113102-20211223.150503-20211224.214103-20211226.003103

guyco33 · 2021-12-26T13:28:35Z

@dain Issue might be related to the recent io.airlift upgrade done on 365 (upgrade from 208 to 209 - 200ec0e)

martint · 2021-12-26T20:42:39Z

For some reason each rotation creates a new symlink

That's intentional. This makes the files append-only, which are easier to handle for software that tails files.

while the actual file name is appended with a new suffix:

That seems like a bug. The prefix should remain constant and the suffix should change for every new file (but not appended to the existing name). cc @dain

dain · 2021-12-26T22:08:28Z

Ya that is definitely a bug

dain · 2022-01-01T20:59:17Z

Here is the Airlift PR airlift/airlift#971

findepi · 2022-01-04T12:24:22Z

The new logger only rolls on size.

Didn't we have date-based rolling?
That used to be convenient.

cc @willmostly @springjd

sajjoseph · 2022-01-04T16:34:09Z

The issue referenced here is affecting our production. Once the log file names reach a certain length, CentOS is not allowing to create fresh ones and so Trino service won't start.

Example server.log file that is generated (this one hasn't reached the max length yet)

server.log-20211201.010845-20211201.012339-20211201.012440-20211201.013539-20211201.013752-20211201.014907-20211210.232940-20211211.043859-20211221.190243-20211221.205350-20220104.134506

Current fix is to delete the log files and restart the service. Looking forward to see the airlift patch merged and get it added to the upcoming release.

guyco33 · 2022-01-17T08:55:58Z

@martint @dain Issue still not resolved.

findepi · 2022-01-17T10:50:38Z

Which milestone is this closed in?

dain · 2022-01-18T18:25:25Z

BTW, there is a kill switch for the new logging code: log.legacy-implementation.enabled

dain · 2022-01-18T22:34:59Z

I write more tests and could not reproduce this behavior. Also, ran the dev server with config.properties:

log.path=/tmp/dain/trino
log.enable-console=false

and it worked as expected:

[14:31 dain@lazypro:~] ls -la /tmp/dain/
total 408
drwxr-xr-x   4 dain  wheel     128 Jan 18 14:30 ./
drwxrwxrwt  17 root  wheel     544 Jan 18 14:30 ../
lrwxr-xr-x   1 dain  wheel      31 Jan 18 14:30 trino@ -> /tmp/dain/trino-20220118.143025
-rw-r--r--   1 dain  wheel  172605 Jan 18 14:30 trino-20220118.143025
[14:31 dain@lazypro:~] ls -la /tmp/dain/
total 816
drwxr-xr-x   5 dain  wheel     160 Jan 18 14:31 ./
drwxrwxrwt  17 root  wheel     544 Jan 18 14:30 ../
lrwxr-xr-x   1 dain  wheel      31 Jan 18 14:31 trino@ -> /tmp/dain/trino-20220118.143139
-rw-r--r--   1 dain  wheel  172605 Jan 18 14:30 trino-20220118.143025
-rw-r--r--   1 dain  wheel  172604 Jan 18 14:31 trino-20220118.143139
[14:31 dain@lazypro:~] ls -la /tmp/dain/
total 1224
drwxr-xr-x   6 dain  wheel     192 Jan 18 14:32 ./
drwxrwxrwt  17 root  wheel     544 Jan 18 14:30 ../
lrwxr-xr-x   1 dain  wheel      31 Jan 18 14:32 trino@ -> /tmp/dain/trino-20220118.143244
-rw-r--r--   1 dain  wheel  172605 Jan 18 14:30 trino-20220118.143025
-rw-r--r--   1 dain  wheel  172720 Jan 18 14:32 trino-20220118.143139
-rw-r--r--   1 dain  wheel  172604 Jan 18 14:32 trino-20220118.143244
[14:32 dain@lazypro:~] ls -la /tmp/dain/
total 1632
drwxr-xr-x   7 dain  wheel     224 Jan 18 14:33 ./
drwxrwxrwt  17 root  wheel     544 Jan 18 14:30 ../
lrwxr-xr-x   1 dain  wheel      31 Jan 18 14:33 trino@ -> /tmp/dain/trino-20220118.143304
-rw-r--r--   1 dain  wheel  172605 Jan 18 14:30 trino-20220118.143025
-rw-r--r--   1 dain  wheel  172720 Jan 18 14:32 trino-20220118.143139
-rw-r--r--   1 dain  wheel  172720 Jan 18 14:33 trino-20220118.143244
-rw-r--r--   1 dain  wheel  172604 Jan 18 14:33 trino-20220118.143304

guyco33 · 2022-01-19T08:51:02Z

In my installation logs are created in node.data-dir under /data/trino/var/log/

Trying to set log.path in config.properties results with launcher failure:

1) Configuration property 'log.output-file' (=/data/trino/var/log/server.log-20220119.075748-20220119.075935-20220119.075945-20220119.082332) conflicts with property 'log.path' (=/tmp/guy/trino)

2) Configuration property 'log.output-file' has been replaced. Use 'log.path' instead.

2 errors
com.google.inject.ConfigurationException: Guice configuration errors:

1) Configuration property 'log.output-file' (=/data/trino/var/log/server.log-20220119.075748-20220119.075935-20220119.075945-20220119.082332) conflicts with property 'log.path' (=/tmp/guy/trino)

2) Configuration property 'log.output-file' has been replaced. Use 'log.path' instead.

2 errors
	at io.airlift.configuration.Problems.getException(Problems.java:135)
	at io.airlift.configuration.Problems.throwIfHasErrors(Problems.java:73)
	at io.airlift.configuration.ConfigurationFactory.findOperativeInjectionPoint(ConfigurationFactory.java:521)
	at io.airlift.configuration.ConfigurationFactory.setConfigProperty(ConfigurationFactory.java:456)
	at io.airlift.configuration.ConfigurationFactory.build(ConfigurationFactory.java:375)
	at io.airlift.configuration.ConfigurationFactory.build(ConfigurationFactory.java:303)
	at io.airlift.configuration.ConfigurationFactory.build(ConfigurationFactory.java:298)
	at io.airlift.bootstrap.Bootstrap.initialize(Bootstrap.java:212)
	at io.trino.server.Server.doStart(Server.java:117)
	at io.trino.server.Server.lambda$start$0(Server.java:78)
	at io.trino.$gen.Trino_368____20220119_082442_1.run(Unknown Source)
	at io.trino.server.Server.start(Server.java:78)
	at io.trino.server.TrinoServer.main(TrinoServer.java:38)

dain · 2022-01-19T22:18:52Z

The bug is in the launcher python script in airlift: airlift/airlift#978

guyco33 · 2022-01-20T07:29:02Z

Approve that airlift/airlift#978 fixes the issue. Thanks @dain

guyco33 · 2022-01-20T07:31:09Z

Issue will be closed after Bumping Trino with a new airlift version

findepi · 2022-01-20T08:28:43Z

airlift/airlift#971 , airlift/airlift#978, airlift/airlift#980, airlift/airlift#974 ...
sounds like we should have a test for the logging subsystem.

guyco33 changed the title ~~Server.log file stopped rotating since 365~~ Bad server.log rotation reaches filename length limits (since 365) Dec 26, 2021

guyco33 added bug Something isn't working invalid labels Dec 26, 2021

guyco33 removed the invalid label Dec 27, 2021

martint added the RELEASE-BLOCKER label Dec 30, 2021

martint mentioned this issue Jan 10, 2022

Update to airlift 213 #10526

Merged

martint closed this as completed in #10526 Jan 11, 2022

guyco33 reopened this Jan 17, 2022

guyco33 closed this as completed Jan 20, 2022

guyco33 reopened this Jan 20, 2022

martint mentioned this issue Jan 21, 2022

Update to airlift 214 #10738

Merged

martint closed this as completed in #10738 Jan 25, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Bad server.log rotation reaches filename length limits (since 365) #10394

Bad server.log rotation reaches filename length limits (since 365) #10394

guyco33 commented Dec 23, 2021 •

edited

kokosing commented Dec 23, 2021

bitweld commented Dec 23, 2021

guyco33 commented Dec 23, 2021

dain commented Dec 23, 2021

guyco33 commented Dec 26, 2021

guyco33 commented Dec 26, 2021 •

edited

martint commented Dec 26, 2021

dain commented Dec 26, 2021

dain commented Jan 1, 2022

findepi commented Jan 4, 2022

sajjoseph commented Jan 4, 2022

guyco33 commented Jan 17, 2022

findepi commented Jan 17, 2022

dain commented Jan 18, 2022

dain commented Jan 18, 2022

guyco33 commented Jan 19, 2022

dain commented Jan 19, 2022

guyco33 commented Jan 20, 2022

guyco33 commented Jan 20, 2022

findepi commented Jan 20, 2022 •

edited

Bad server.log rotation reaches filename length limits (since 365) #10394

Bad server.log rotation reaches filename length limits (since 365) #10394

Comments

guyco33 commented Dec 23, 2021 • edited

kokosing commented Dec 23, 2021

bitweld commented Dec 23, 2021

guyco33 commented Dec 23, 2021

dain commented Dec 23, 2021

guyco33 commented Dec 26, 2021

guyco33 commented Dec 26, 2021 • edited

martint commented Dec 26, 2021

dain commented Dec 26, 2021

dain commented Jan 1, 2022

findepi commented Jan 4, 2022

sajjoseph commented Jan 4, 2022

guyco33 commented Jan 17, 2022

findepi commented Jan 17, 2022

dain commented Jan 18, 2022

dain commented Jan 18, 2022

guyco33 commented Jan 19, 2022

dain commented Jan 19, 2022

guyco33 commented Jan 20, 2022

guyco33 commented Jan 20, 2022

findepi commented Jan 20, 2022 • edited

guyco33 commented Dec 23, 2021 •

edited

guyco33 commented Dec 26, 2021 •

edited

findepi commented Jan 20, 2022 •

edited