server log question

[Jeximo]

Hi all, and especially @phymbert. I think what you do is very important.

My question is about server logging. Readme shows --log-format & --log-disable.

By default --log-disable is Enabled, which is confusing. Further, I don't see a log in any format as a result of using --log-format. So, I'm not getting a proper log, and I don't see how to aquire one for server.

./build/bin/server -m ~/WizardLM-2-7B-IQ4_XS.gguf -t 3 -c 2048 --log-format text

[1713621145] warming up the model with an empty run
INFO [                    init] initializing slots | tid="532689188096" timestamp=1713621148 n_slots=1
INFO [                    init] new slot | tid="532689188096" timestamp=1713621148 id_slot=0 n_ctx_slot=2048
INFO [                    main] model loaded | tid="532689188096" timestamp=1713621148
INFO [                    main] chat template | tid="532689188096" timestamp=1713621148 chat_example="<|im_start|>system\nYou are a helpful assistant<|im_end|>\n<|im_start|>user\nHello<|im_end|>\n<|im_start|>assistant\nHi there<|im_end|>\n<|im_start|>user\nHow are you?<|im_end|>\n<|im_start|>assistant\n" built_in=true
INFO [                    main] HTTP server listening | tid="532689188096" timestamp=1713621148 n_threads_http="7" port="8080" hostname="127.0.0.1"
INFO [            update_slots] all slots are idle | tid="532689188096" timestamp=1713621148
INFO [      log_server_request] request | tid="515573947648" timestamp=1713621177 remote_addr="127.0.0.1" remote_port=41674 status=200 method="GET" path="/" params={}                                 
INFO [      log_server_request] request | tid="515573947648" timestamp=1713621177 remote_addr="127.0.0.1" remote_port=41674 status=200 method="GET" path="/index.js" params={}                          
INFO [      log_server_request] request | tid="515572911360" timestamp=1713621177 remote_addr="127.0.0.1" remote_port=41678 status=200 method="GET" path="/json-schema-to-grammar.mjs" params={}        
INFO [      log_server_request] request | tid="515571875072" timestamp=1713621177 remote_addr="127.0.0.1" remote_port=41676 status=200 method="GET" path="/completion.js" params={}                     
INFO [      log_server_request] request | tid="515571875072" timestamp=1713621177 remote_addr="127.0.0.1" remote_port=41676 status=404 method="GET" path="/favicon.ico" params={}
INFO [   launch_slot_with_task] slot is processing task | tid="532689188096" timestamp=1713621186 id_slot=0 id_task=0                                
INFO [            update_slots] kv cache rm [p0, end) | tid="532689188096" timestamp=1713621186 id_slot=0 id_task=0 p0=0                              
INFO [           print_timings] prompt eval time     =   23387.91 ms /    61 tokens (  383.41 ms per token,     2.61 tokens per second) | tid="532689188096" timestamp=1713621220 id_slot=0 id_task=0 t_prompt_processing=23387.913 n_prompt_tokens_processed=61 t_token=383.4084098360656 n_tokens_second=2.608184834619489
INFO [           print_timings] generation eval time =   10833.40 ms /    24 runs   (  451.39 ms per token,     2.22 tokens per second) | tid="532689188096" timestamp=1713621220 id_slot=0 id_task=0 t_token_generation=10833.396 n_decoded=24 t_token=451.3915 n_tokens_second=2.2153718003108165         
INFO [           print_timings]           total time =   34221.31 ms | tid="532689188096" timestamp=1713621220 id_slot=0 id_task=0 t_prompt_processing=23387.913 t_token_generation=10833.396 t_total=34221.309
INFO [            update_slots] slot released | tid="532689188096" timestamp=1713621220 id_slot=0 id_task=0 n_ctx=2048 n_past=84 n_system_tokens=0 n_cache_tokens=84 truncated=false
INFO [            update_slots] all slots are idle | tid="532689188096" timestamp=1713621220
INFO [      log_server_request] request | tid="515554061568" timestamp=1713621220 remote_addr="127.0.0.1" remote_port=41680 status=200 method="POST" path="/completion" params={}                       
INFO [            update_slots] all slots are idle | tid="532689188096" timestamp=1713621220
^CINFO [            update_slots] all slots are idle | tid="532689188096" timestamp=1713621272

I expected llama.log to include everything, including the conversation for this run:

Instead llama.log recorded, "warming up the model with an empty run", and that's all.

Does CTRL + C to kill the server block logging somehow? Am I missing something obvious?

[phymbert]

Hello @Jeximo, thanks, appreciated.

Logging in the server is confusing yes, we did some attempts to improve here:

• server: logs - unified format and --log-format option #5700

But I agree it must be continued, kind of old technical debt here.

• Server does not use classical LLAMA_LOG_* so all server logs go only to stdout.
• --log-disable, actually switch log from the file llama.log to stderr. It is actually not enabled by default, the doc is misleading: Enabled mean not disabled...

if you could open an issue to sumarize all the issues and to discuss possible solution, it would be great.

[Jeximo]

Server does not use classical LLAMA_LOG_* so all server logs go only to stdout.

Ahh, this makes sense to me. I see how --log-format affects output now.

if you could open an issue to sumarize all the issues and to discuss possible solution, it would be great.

This is reasonable, and I'll consider it after collecting more info.

Thank you.

[phymbert]

Also I forgot to mention --verbose server param

[Jeximo]

Oh yah, --verbose + --log-output text is what I wanted. Thanks, good to know!