search

dCache / dcache

dCache - a system for storing and retrieving huge amounts of data, distributed among a large number of heterogenous server nodes, under a single virtual filesystem tree with a variety of standard access methods
https://dcache.org
291 stars 136 forks source link

access/event log writing broken #3742

Open calestyo opened 7 years ago

calestyo commented 7 years ago

Hi.

Again, 3.2.8, Debian/systemd.

I've modified logback.xml as attached (basically just the timestamp format and the access/even logs are written to some subdir. logback.xml.txt

In earlier dcaches (3.1) this worked fine, but now there seem to be some permission issues.

logback creates the dirs, i.e.:

/var/log/dcache# ls -al
total 168k
drwxr-xr-x  4 dcache dcache 4,1k Nov 28 17:58 .
drwxr-xr-x 14 root   root    74k Nov 28 00:39 ..
drwxr-xr-x  2 root   root   4,1k Nov 28 17:57 access
drwxr-xr-x  2 root   root   4,1k Nov 28 17:57 events

but it creates them with owner root:root (which I think it did as well before)... but now it apparently tries to create the actual event/access log files with the user of the domain (in most cases dcache).

Thus my pools/etc. logs are full of things like:

root@lcg-lrz-dc13:/var/log/dcache# cat pool_lcg-lrz-dc13_4.log
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:38,924 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:38,925 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:38,925 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [jar:file:/usr/share/dcache/classes/logback-console-config-3.2.8.jar!/logback.xml]
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:38,979 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@102cec62 - URL [jar:file:/usr/share/dcache/classes/logback-console-config-3.2.8.jar!/logback.xml] is not of type file
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:39,124 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:39,131 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:39,156 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDERR]
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:39,203 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:39,302 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:39,303 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDERR] to Logger[ROOT]
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:39,304 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:39,305 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@74f6c5d8 - Registering current configuration as safe fallback point
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,527 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,528 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,529 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [stdout]
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,529 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,532 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [dmg.util.PinboardAppender]
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,534 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [pinboard]
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,545 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.PatternLayout] for [layout] property
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,598 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,601 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [events]
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,686 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - Will use gz compression
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,689 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - Will use the pattern /var/log/dcache/events/pool_lcg-lrz-dc13_4.log.%d{yyyy-MM-dd} for the active file
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,695 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - The date pattern is 'yyyy-MM-dd' from file name pattern '/var/log/dcache/events/pool_lcg-lrz-dc13_4.log.%d{yyyy-MM-dd}.gz'.
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,695 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Roll-over at midnight.
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,699 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Setting initial period to Tue Nov 28 17:57:40 CET 2017
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,701 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,704 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[events] - Active log file name: /var/log/dcache/events/pool_lcg-lrz-dc13_4.log
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,704 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[events] - File property is set to [/var/log/dcache/events/pool_lcg-lrz-dc13_4.log]
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,706 |-ERROR in ch.qos.logback.core.rolling.RollingFileAppender[events] - openFile(/var/log/dcache/events/pool_lcg-lrz-dc13_4.log,true) call failed. java.io.FileNotFoundException: /var/log/dcache/events/pool_lcg-lrz-dc13_4.log (Permission denied)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at java.io.FileNotFoundException: /var/log/dcache/events/pool_lcg-lrz-dc13_4.log (Permission denied)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at java.io.FileOutputStream.open0(Native Method)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at java.io.FileOutputStream.open(FileOutputStream.java:270)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at java.io.FileOutputStream.<init>(FileOutputStream.java:213)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.recovery.ResilientFileOutputStream.<init>(ResilientFileOutputStream.java:28)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.FileAppender.openFile(FileAppender.java:149)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.FileAppender.start(FileAppender.java:108)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.rolling.RollingFileAppender.start(RollingFileAppender.java:86)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.joran.action.AppenderAction.end(AppenderAction.java:96)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.joran.spi.Interpreter.callEndAction(Interpreter.java:317)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:196)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:182)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:62)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:149)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:135)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:99)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:49)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at org.dcache.boot.Domain.initializeLogging(Domain.java:194)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at org.dcache.boot.Domain.start(Domain.java:127)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at org.dcache.boot.BootLoader.main(BootLoader.java:125)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,706 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,706 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [access]
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,707 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - Will use gz compression
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,725 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - Will use the pattern /var/log/dcache/access/pool_lcg-lrz-dc13_4.log.%d{yyyy-MM-dd} for the active file
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,726 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - The date pattern is 'yyyy-MM-dd' from file name pattern '/var/log/dcache/access/pool_lcg-lrz-dc13_4.log.%d{yyyy-MM-dd}.gz'.
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,726 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Roll-over at midnight.
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,726 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Setting initial period to Tue Nov 28 17:57:40 CET 2017
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,727 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,727 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[access] - Active log file name: /var/log/dcache/access/pool_lcg-lrz-dc13_4.log
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,727 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[access] - File property is set to [/var/log/dcache/access/pool_lcg-lrz-dc13_4.log]
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:40,727 |-ERROR in ch.qos.logback.core.rolling.RollingFileAppender[access] - openFile(/var/log/dcache/access/pool_lcg-lrz-dc13_4.log,true) call failed. java.io.FileNotFoundException: /var/log/dcache/access/pool_lcg-lrz-dc13_4.log (Permission denied)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at java.io.FileNotFoundException: /var/log/dcache/access/pool_lcg-lrz-dc13_4.log (Permission denied)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at java.io.FileOutputStream.open0(Native Method)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at java.io.FileOutputStream.open(FileOutputStream.java:270)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at java.io.FileOutputStream.<init>(FileOutputStream.java:213)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.recovery.ResilientFileOutputStream.<init>(ResilientFileOutputStream.java:28)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.FileAppender.openFile(FileAppender.java:149)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.FileAppender.start(FileAppender.java:108)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.rolling.RollingFileAppender.start(RollingFileAppender.java:86)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.joran.action.AppenderAction.end(AppenderAction.java:96)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.joran.spi.Interpreter.callEndAction(Interpreter.java:317)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:196)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:182)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:62)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:149)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:135)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:99)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:49)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at org.dcache.boot.Domain.initializeLogging(Domain.java:194)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at org.dcache.boot.Domain.start(Domain.java:127)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: #011at #011at org.dcache.boot.BootLoader.main(BootLoader.java:125)
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:41,831 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [stdout] to Logger[ROOT]
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:41,831 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [pinboard] to Logger[ROOT]
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,020 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [org.dcache.events] to false
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,020 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [events] to Logger[org.dcache.events]
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,020 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [org.dcache.access] to false
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,020 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [access] to Logger[org.dcache.access]
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,020 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [dummy] to OFF
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,020 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [stdout] to Logger[dummy]
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,020 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [pinboard] to Logger[dummy]
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,020 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [events] to Logger[dummy]
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,020 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [access] to Logger[dummy]
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,293 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [dmg.util.logback.Threshold] for [threshold] property
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,296 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [dmg.util.logback.Threshold] for [threshold] property
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,296 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [dmg.util.logback.Threshold] for [threshold] property
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,297 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [dmg.util.logback.Threshold] for [threshold] property
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,297 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [dmg.util.logback.Threshold] for [threshold] property
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,297 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [dmg.util.logback.Threshold] for [threshold] property
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,298 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [dmg.util.logback.Threshold] for [threshold] property
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,298 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [dmg.util.logback.Threshold] for [threshold] property
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,309 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [dmg.util.logback.Threshold] for [threshold] property
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,328 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [dmg.util.logback.Threshold] for [threshold] property
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,328 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [dmg.util.logback.Threshold] for [threshold] property
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,436 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [dmg.util.logback.Threshold] for [threshold] property
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,437 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [dmg.util.logback.Threshold] for [threshold] property
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,466 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [dmg.util.logback.Threshold] for [threshold] property
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,630 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
Nov 28 17:57:42 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 17:57:42,631 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@43015c69 - Registering current configuration as safe fallback point
Nov 28 17:57:57 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 2017-11-28 17:57:57+01:00 (lcg-lrz-dc13_4) [] Pool mode changed to disabled(fetch,store,stage,p2p-client,p2p-server): Awaiting initialization
Nov 28 17:57:57 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 2017-11-28 17:57:57+01:00 (lcg-lrz-dc13_4) [] Pool mode changed to disabled(store,stage,p2p-client): Loading...
Nov 28 17:57:57 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 2017-11-28 17:57:57+01:00 (lcg-lrz-dc13_4) [] Reading inventory from [data=/srv/dcache/pools/4/data;meta=/srv/dcache/pools/4/meta].
Nov 28 17:58:12 lcg-lrz-dc13 dcache@pool_lcg-lrz-dc13_4[44128]: 2017-11-28 17:58:12+01:00 (lcg-lrz-dc13_4) [] Pool mode changed to enabled

Any ideas?

Cheers, Chris.

calestyo commented 7 years ago

I just see: On other nodes the dirs are created as dcache:dcache... so maybe the above isn't new at all and I just never noticed it before ^^

Still the problem is basically that with different users, the log files/dirs are still created (in some cases) as non-root.

I think on Debian they should be owned root:adm ... even if the actual daemon runs as another user. E.g. Apache runs as www-data, but still, the logs are root:adm.

paulmillar commented 7 years ago

This looks like logback is using some kind of default configuration initially, before switching to the real configuration (usually /etc/dcache/logback.xml).

calestyo commented 7 years ago

Well to me it looks like "the first domain wins"... i.e. one the one node where I see the issue there is a webdav door (running as root for port 80/443 binding)... and pool services (running as dcache).

If webdav is started first, it may simply create event/access at these users.

I think this issue actually roots in what I was talking about in the other systemd-related issues: IMO, dcache should normally run always as user dcache, and just bind to ports, open log files, etc. shortly before it drops privileges from root.

systemd might provide better ways for this... (not sure)... e.g. there are things like AmbientCapabilities= which one could set to allow binding to privileged ports (and dCache could later drop that privilige... if Java supports such thing.

paulmillar commented 7 years ago

Chris, it would be helpful if you limited a report to a single issue.

For example, there appears to be (at least) three issues:

  1. that directories are auto-created with "inappropriate" ownership ("root" vs "dcache"),
  2. that log files contain unexpected content on domain start-up,
  3. that dCache must run as user root to provide services on privileged ports (such as port 80).

On item 1. I would put this down as somewhere between a feature request and a simple admin error. You modified the logback configuration to use different directories without first creating those directories. If dCache is running as root then it will auto-create those directories with root ownership: logback provides no controls on how parent directories are created. If you care about ownership and permissions of those directories then you should create them with the correct values (since you editing the logback.xml file). For comparison, note that the dCache packaging takes care of the /var/log/dcache directory, which the default logback configuration targets (at least, for non-systemd packages).

On item 2. this looks like a bug and needs further investigation.

On item 3. Java simply does not support "dropping privileges" (either changing effective uid or dropping capabilities). Feel free to give systemd's AmbientCapabilities a go. I had some success running dCache with CAP_NET_BIND_SERVICE (outside of systemd), but it required some rather intrusive changes to the OpenJDK packaged files. It would be good to learn whether this is a realistic option with systemd.