Bug: WebBackend web.config settings are ignored #738
Description
Basic Info
- Version: latest dev (bd98280)
- Java Version: OpenJDK 24
Description
Changing the values of DEBUG, LOG_FILE_PATH, and LOG_LEVEL in web.config.properties appears to have no effect.
Additionally, DEBUG is not in the default web.config, but is mentioned in the README.
When running WebBackend.exe or WebBackendc.exe I expect logging to use the configured LOG_LEVEL=INFO, but it continues to log on DEBUG level.
The file from LOG_FILE_PATH is also never created or written to.
Writing to the console is very slow on Windows and takes the majority of processing time when making a request.
Redirecting to a file or even NUL is also slow.
Example logs after start (unwanted jetty DEBUG):
de.uni_freiburg.informatik.ultimate.web.backend [de.uni_freiburg.informatik.ultimate.web.backend.Config] INFO : Loaded settings file from web.config.properties
de.uni_freiburg.informatik.ultimate.web.backend [de.uni_freiburg.informatik.ultimate.web.backend.UserSettingsWhitelist] INFO : Loaded user settings whitelist
org.eclipse.jetty.http [org.eclipse.jetty.http.PreEncodedHttpField] DEBUG : loaded 0 HttpFieldPreEncoders
org.eclipse.jetty.util [org.eclipse.jetty.util.component.ContainerLifeCycle] DEBUG : QueuedThreadPool@3aa3193a added {org.eclipse.jetty.util.thread.ThreadPoolBudget@7fb9f71f,POJO}
org.eclipse.jetty.util [org.eclipse.jetty.util.component.ContainerLifeCycle] DEBUG : Server@1364127192 added {QueuedThreadPool[qtp983767354]@3aa3193a{STOPPED,8<=0<=200,i=0,r=-1,t=-5969992ms,q=0}[NO_TRY],AUTO}
org.eclipse.jetty.util [org.eclipse.jetty.util.component.ContainerLifeCycle] DEBUG : Server@1364127192 added {oejut.ScheduledExecutorScheduler@5f7f2382{STOPPED},AUTO}
org.eclipse.jetty.util [org.eclipse.jetty.util.component.ContainerLifeCycle] DEBUG : Server@1364127192 added {org.eclipse.jetty.io.ArrayByteBufferPool@27cf3151{min=0,max=65536,buckets=16,heap=0/536870912,direct=0/536870912},POJO}
org.eclipse.jetty.util [org.eclipse.jetty.util.component.ContainerLifeCycle] DEBUG : Server@1364127192 added {org.eclipse.jetty.util.resource.FileSystemPool@34abdee4,UNMANAGED}
org.eclipse.jetty.util [org.eclipse.jetty.util.component.ContainerLifeCycle] DEBUG : HttpConnectionFactory@1082865087 added {HttpConfiguration@29ad44e3{32768/8192,8192/8192,https://:0,[]},POJO}
(...)
org.eclipse.jetty.util [org.eclipse.jetty.util.component.ContainerLifeCycle] DEBUG : ServletHandler@11963225 added {de.uni_freiburg.informatik.ultimate.web.backend.UltimateApiServlet-78dc4696==de.uni_freiburg.informatik.ultimate.web.backend.UltimateApiServlet@1989e6b5{jsp=null,order=-1,inst=false,async=true,src=EMBEDDED:<null>,STOPPED},AUTO}
org.eclipse.jetty.util [org.eclipse.jetty.util.component.ContainerLifeCycle] DEBUG : ServletHandler@11963225 added {[/api/*]=>de.uni_freiburg.informatik.ultimate.web.backend.UltimateApiServlet-78dc4696,POJO}
org.eclipse.jetty.util [org.eclipse.jetty.util.component.ContainerLifeCycle] DEBUG : ServletHandler@11963225 added {de.uni_freiburg.informatik.ultimate.web.backend.util.CrossOriginFilter-7b22ec89==de.uni_freiburg.informatik.ultimate.web.backend.util.CrossOriginFilter@7b22ec89{inst=false,async=true,src=EMBEDDED:<null>},AUTO}
org.eclipse.jetty.util [org.eclipse.jetty.util.component.ContainerLifeCycle] DEBUG : ServletHandler@11963225 added {[/*]/[]/[]=>de.uni_freiburg.informatik.ultimate.web.backend.util.CrossOriginFilter-7b22ec89,POJO}
de.uni_freiburg.informatik.ultimate.web.backend [de.uni_freiburg.informatik.ultimate.web.backend.WebBackend] INFO : Serving API at route: /api
org.eclipse.jetty.util [org.eclipse.jetty.util.component.AbstractLifeCycle] DEBUG : STARTING oejs.Server@514eedd8{STOPPED}[12.0.9,sto=0]
Example log when making a request to the server, where it logs every byte received:
org.eclipse.jetty.ee8.server [org.eclipse.jetty.ee8.nested.HttpChannel] DEBUG : handle http://192.168.10.100:8080/api HttpChannel@43674142{s=HttpChannelState@168e8303{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=http://192.168.10.100:8080/api,age=33}
(...)
org.eclipse.jetty.ee8.server [org.eclipse.jetty.ee8.nested.AsyncContentProducer] DEBUG : produceRawContent updated rawContentArrived to 7902 and firstByteTimeStamp to 5980584960300 AsyncContentProducer@4ea97200[r=null,t=null,i=null,error=false,c=HttpChannel@43674142{s=HttpChannelState@168e8303{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=http://192.168.10.100:8080/api,age=46}]
org.eclipse.jetty.ee8.server [org.eclipse.jetty.ee8.nested.AsyncContentProducer] DEBUG : produceRawContent produced @731ef25f{DirectByteBufferR@1d1fe964[p=290,l=8192,c=8192,r=7902]={POST /api...F-8\r\n\r\n<<<code_file_extension=.c&us...NCES%22%2C%22TAIPAN%22%>>>},spc=false,eof=false,err=null} AsyncContentProducer@4ea97200[r=null,t=null,i=null,error=false,c=HttpChannel@43674142{s=HttpChannelState@168e8303{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=http://192.168.10.100:8080/api,age=46}]
org.eclipse.jetty.ee8.server [org.eclipse.jetty.ee8.nested.AsyncContentProducer] DEBUG : transforming raw content AsyncContentProducer@4ea97200[r=@731ef25f{DirectByteBufferR@1d1fe964[p=290,l=8192,c=8192,r=7902]={POST /api...F-8\r\n\r\n<<<code_file_extension=.c&us...NCES%22%2C%22TAIPAN%22%>>>},spc=false,eof=false,err=null},t=null,i=null,error=false,c=HttpChannel@43674142{s=HttpChannelState@168e8303{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=http://192.168.10.100:8080/api,age=46}]
org.eclipse.jetty.ee8.server [org.eclipse.jetty.ee8.nested.AsyncContentProducer] DEBUG : no interceptor, transformed content is raw content AsyncContentProducer@4ea97200[r=@731ef25f{DirectByteBufferR@1d1fe964[p=290,l=8192,c=8192,r=7902]={POST /api...F-8\r\n\r\n<<<code_file_extension=.c&us...NCES%22%2C%22TAIPAN%22%>>>},spc=false,eof=false,err=null},t=null,i=null,error=false,c=HttpChannel@43674142{s=HttpChannelState@168e8303{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=http://192.168.10.100:8080/api,age=46}]
org.eclipse.jetty.ee8.server [org.eclipse.jetty.ee8.nested.AsyncContentProducer] DEBUG : transformed content not yet depleted, returning it AsyncContentProducer@4ea97200[r=@731ef25f{DirectByteBufferR@1d1fe964[p=290,l=8192,c=8192,r=7902]={POST /api...F-8\r\n\r\n<<<code_file_extension=.c&us...NCES%22%2C%22TAIPAN%22%>>>},spc=false,eof=false,err=null},t=@731ef25f{DirectByteBufferR@1d1fe964[p=290,l=8192,c=8192,r=7902]={POST /api...F-8\r\n\r\n<<<code_file_extension=.c&us...NCES%22%2C%22TAIPAN%22%>>>},spc=false,eof=false,err=null},i=null,error=false,c=HttpChannel@43674142{s=HttpChannelState@168e8303{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=http://192.168.10.100:8080/api,age=46}]
org.eclipse.jetty.ee8.server [org.eclipse.jetty.ee8.nested.AsyncContentProducer] DEBUG : nextContent = @731ef25f{DirectByteBufferR@1d1fe964[p=290,l=8192,c=8192,r=7902]={POST /api...F-8\r\n\r\n<<<code_file_extension=.c&us...NCES%22%2C%22TAIPAN%22%>>>},spc=false,eof=false,err=null} AsyncContentProducer@4ea97200[r=@731ef25f{DirectByteBufferR@1d1fe964[p=290,l=8192,c=8192,r=7902]={POST /api...F-8\r\n\r\n<<<code_file_extension=.c&us...NCES%22%2C%22TAIPAN%22%>>>},spc=false,eof=false,err=null},t=@731ef25f{DirectByteBufferR@1d1fe964[p=290,l=8192,c=8192,r=7902]={POST /api...F-8\r\n\r\n<<<code_file_extension=.c&us...NCES%22%2C%22TAIPAN%22%>>>},spc=false,eof=false,err=null},i=null,error=false,c=HttpChannel@43674142{s=HttpChannelState@168e8303{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=http://192.168.10.100:8080/api,age=46}]
org.eclipse.jetty.ee8.server [org.eclipse.jetty.ee8.nested.HttpChannelState] DEBUG : onReadIdle HttpChannelState@168e8303{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0}
org.eclipse.jetty.ee8.server [org.eclipse.jetty.ee8.nested.BlockingContentProducer] DEBUG : nextContent async producer returned @731ef25f{DirectByteBufferR@1d1fe964[p=290,l=8192,c=8192,r=7902]={POST /api...F-8\r\n\r\n<<<code_file_extension=.c&us...NCES%22%2C%22TAIPAN%22%>>>},spc=false,eof=false,err=null}
org.eclipse.jetty.ee8.server [org.eclipse.jetty.ee8.nested.HttpInput] DEBUG : read produced 1 byte(s) HttpInput@1759352172 cs=HttpChannelState@168e8303{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0} cp=org.eclipse.jetty.ee8.nested.BlockingContentProducer@6d53958b eof=false
org.eclipse.jetty.ee8.server [org.eclipse.jetty.ee8.nested.AsyncContentProducer] DEBUG : checkMinDataRate [m=0,t=5980584960300] AsyncContentProducer@4ea97200[r=@731ef25f{DirectByteBufferR@1d1fe964[p=291,l=8192,c=8192,r=7901]={POST /api...-8\r\n\r\nc<<<ode_file_extension=.c&use...NCES%22%2C%22TAIPAN%22%>>>},spc=false,eof=false,err=null},t=@731ef25f{DirectByteBufferR@1d1fe964[p=291,l=8192,c=8192,r=7901]={POST /api...-8\r\n\r\nc<<<ode_file_extension=.c&use...NCES%22%2C%22TAIPAN%22%>>>},spc=false,eof=false,err=null},i=null,error=false,c=HttpChannel@43674142{s=HttpChannelState@168e8303{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=http://192.168.10.100:8080/api,age=47}]
org.eclipse.jetty.ee8.server [org.eclipse.jetty.ee8.nested.AsyncContentProducer] DEBUG : nextTransformedContent AsyncContentProducer@4ea97200[r=@731ef25f{DirectByteBufferR@1d1fe964[p=291,l=8192,c=8192,r=7901]={POST /api...-8\r\n\r\nc<<<ode_file_extension=.c&use...NCES%22%2C%22TAIPAN%22%>>>},spc=false,eof=false,err=null},t=@731ef25f{DirectByteBufferR@1d1fe964[p=291,l=8192,c=8192,r=7901]={POST /api...-8\r\n\r\nc<<<ode_file_extension=.c&use...NCES%22%2C%22TAIPAN%22%>>>},spc=false,eof=false,err=null},i=null,error=false,c=HttpChannel@43674142{s=HttpChannelState@168e8303{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=http://192.168.10.100:8080/api,age=47}]
org.eclipse.jetty.ee8.server [org.eclipse.jetty.ee8.nested.AsyncContentProducer] DEBUG : transformed content not yet depleted, returning it AsyncContentProducer@4ea97200[r=@731ef25f{DirectByteBufferR@1d1fe964[p=291,l=8192,c=8192,r=7901]={POST /api...-8\r\n\r\nc<<<ode_file_extension=.c&use...NCES%22%2C%22TAIPAN%22%>>>},spc=false,eof=false,err=null},t=@731ef25f{DirectByteBufferR@1d1fe964[p=291,l=8192,c=8192,r=7901]={POST /api...-8\r\n\r\nc<<<ode_file_extension=.c&use...NCES%22%2C%22TAIPAN%22%>>>},spc=false,eof=false,err=null},i=null,error=false,c=HttpChannel@43674142{s=HttpChannelState@168e8303{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=http://192.168.10.100:8080/api,age=47}]
org.eclipse.jetty.ee8.server [org.eclipse.jetty.ee8.nested.AsyncContentProducer] DEBUG : nextContent = @731ef25f{DirectByteBufferR@1d1fe964[p=291,l=8192,c=8192,r=7901]={POST /api...-8\r\n\r\nc<<<ode_file_extension=.c&use...NCES%22%2C%22TAIPAN%22%>>>},spc=false,eof=false,err=null} AsyncContentProducer@4ea97200[r=@731ef25f{DirectByteBufferR@1d1fe964[p=291,l=8192,c=8192,r=7901]={POST /api...-8\r\n\r\nc<<<ode_file_extension=.c&use...NCES%22%2C%22TAIPAN%22%>>>},spc=false,eof=false,err=null},t=@731ef25f{DirectByteBufferR@1d1fe964[p=291,l=8192,c=8192,r=7901]={POST /api...-8\r\n\r\nc<<<ode_file_extension=.c&use...NCES%22%2C%22TAIPAN%22%>>>},spc=false,eof=false,err=null},i=null,error=false,c=HttpChannel@43674142{s=HttpChannelState@168e8303{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=http://192.168.10.100:8080/api,age=47}]
org.eclipse.jetty.ee8.server [org.eclipse.jetty.ee8.nested.HttpChannelState] DEBUG : onReadIdle HttpChannelState@168e8303{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0}
org.eclipse.jetty.ee8.server [org.eclipse.jetty.ee8.nested.BlockingContentProducer] DEBUG : nextContent async producer returned @731ef25f{DirectByteBufferR@1d1fe964[p=291,l=8192,c=8192,r=7901]={POST /api...-8\r\n\r\nc<<<ode_file_extension=.c&use...NCES%22%2C%22TAIPAN%22%>>>},spc=false,eof=false,err=null}
org.eclipse.jetty.ee8.server [org.eclipse.jetty.ee8.nested.HttpInput] DEBUG : read produced 1 byte(s) HttpInput@1759352172 cs=HttpChannelState@168e8303{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0} cp=org.eclipse.jetty.ee8.nested.BlockingContentProducer@6d53958b eof=false
(...150000 more lines...)