logging messages to error_log with "INFO:" does not work

Tue Jul 4 08:51:20 PDT 2006

Kurt Pfeifle wrote:
> Kurt Pfeifle <kpfeifle at danka.de> wrote (Tuesday 04 July 2006 15:45):
> 
> 
>>Helge Blischke <h.blischke at srz.de> wrote (Tuesday 04 July 2006 14:31):
>>
>>
>>>At least in CUPS 1.1.x, the INFO messages are written to the error_log only if
>>>the log level is at least warning or notice (don't know exactly). With log level
>>>info, the latest info message is saved as the state message in the internal printer's
>>>structure (and dumped inot printers.conf, shown in the web interface, or with the
>>>lpstat command).
>>>
>>>I currently don't know if things have changed with 1.2.x.
>>
>>Thanks for this info, Helge.
>>
>>If I understand correctly, that would mean: if I repeat that same
>>"info level" log message one more time (or if I write another one)
>>on the next line, it should appear in the error_log.
>>
>>I tried it. However, it does neither appear in the error log, nor
>>as a state messsage in printers.conf/web interface/lpstat output...
>>(this one only tested with trunk/r5706 so far, not yet with 1.1.23)
> 
> 
> OK, I tested now with 1.1.23 (SUSE-10.0 packages, "RunAsUser No"). I 
> modified the dummy backend to emit the following messages to stderr 
> each time it is run:
> 
>   echo "EMERG:  This is a \"emergency\" level log message" 1>&2
>   echo "ALERT:  This is a \"alert\" level log message"     1>&2
>   echo "CRIT:   This is a \"critical\" level log message"  1>&2
>   echo "ERROR:  This is a \"error\" level log message"     1>&2
>   echo "WARN:   This is a \"warn\" level log message"      1>&2
>   echo "NOTICE: This is a \"notice\" level log message"    1>&2
>   echo "INFO:   This is a \"info\" level log message"      1>&2
>   echo "INFO:   This is a 2nd \"info\" level log message"  1>&2
>   echo "INFO:   This is a 3rd \"info\" level log message"  1>&2
>   echo "DEBUG:  This is a \"debug\" level log message"     1>&2
>   echo "DEBUG2: This is a \"debug2\" level log message"    1>&2
> 
> 
> This results in the following lines in the error_log and in the web 
> interface, depending on the LogLevel setting:
> 
> 
> "LogLevel info":
> ----------------
> 
> X [04/Jul/2006:17:09:34 +0200] [Job 578] This is a "emergency" level log message
> A [04/Jul/2006:17:09:34 +0200] [Job 578] This is a "alert" level log message
> C [04/Jul/2006:17:09:34 +0200] [Job 578] This is a "critical" level log message
> E [04/Jul/2006:17:09:34 +0200] [Job 578] This is a "error" level log message
> N [04/Jul/2006:17:09:34 +0200] [Job 578] : This is a "notice" level log message
>  
>  soprano:~ # links -dump http://localhost:631/printers/dummy | grep "log message"
>              "This is a 3rd "info" level log message"
> 
> 
> "LogLevel debug":
> -----------------
> 
>  soprano:~ # grep "log message" /var/log/cups/error_log
>  X [04/Jul/2006:17:10:29 +0200] [Job 579] This is a "emergency" level log message
>  A [04/Jul/2006:17:10:29 +0200] [Job 579] This is a "alert" level log message
>  C [04/Jul/2006:17:10:29 +0200] [Job 579] This is a "critical" level log message
>  E [04/Jul/2006:17:10:29 +0200] [Job 579] This is a "error" level log message
>  D [04/Jul/2006:17:10:29 +0200] [Job 579] WARN:   This is a "warn" level log message
>  N [04/Jul/2006:17:10:29 +0200] [Job 579] : This is a "notice" level log message
>  D [04/Jul/2006:17:10:29 +0200] [Job 579] This is a "debug" level log message
>  
>  soprano:~ # links -dump http://localhost:631/printers/dummy | grep "log message"
>              "This is a 3rd "info" level log message"
> 
> 
> "LogLevel debug2":
> ------------------
> 
>  soprano:~ # grep "log message" /var/log/cups/error_log
>  X [04/Jul/2006:17:12:55 +0200] [Job 580] This is a "emergency" level log message
>  A [04/Jul/2006:17:12:55 +0200] [Job 580] This is a "alert" level log message
>  C [04/Jul/2006:17:12:55 +0200] [Job 580] This is a "critical" level log message
>  E [04/Jul/2006:17:12:55 +0200] [Job 580] This is a "error" level log message
>  D [04/Jul/2006:17:12:55 +0200] [Job 580] WARN:   This is a "warn" level log message
>  N [04/Jul/2006:17:12:55 +0200] [Job 580] : This is a "notice" level log message
>  I [04/Jul/2006:17:12:55 +0200] [Job 580] This is a "info" level log message
>  I [04/Jul/2006:17:12:55 +0200] [Job 580] This is a 2nd "info" level log message
>  I [04/Jul/2006:17:12:55 +0200] [Job 580] This is a 3rd "info" level log message
>  D [04/Jul/2006:17:12:55 +0200] [Job 580] This is a "debug" level log message
>  d [04/Jul/2006:17:12:55 +0200] [Job 580] This is a "debug2" level log message
>  
>  soprano:~ # links -dump http://localhost:631/printers/dummy | grep "log message"
>              "This is a 3rd "info" level log message"
> 
> 
> Note,...
>  ...how the "NOTICE:" line appears with the leading ": "
>  ...how the "INFO:" line only appears in log level debug2
>  ...how the "WARN:" line appears with the "D" marker, and including the "WARN:   "
>  ...how the web interface always keeps the last info level log message
> 
> Cheers,
> Kurt

Just a footnote: our home-grown backends, like hpnpf for JetDirect cards, write
the INFO messages as well as the PS interpreter's stdout to a printer specific
log file. The contents look like the following:
---snip---
INFO: [Wed Jun 28 11:39:53 2006] 63208040000000000000028.fm.ipl.CA5b49 (77368)
INFO: %%[ Error: limitcheck; OffendingCommand: 
imageC3C3C3C3C3C3C3C3C5C4C3C2C1BFBEBEBDBDBEBEBFBFC0C0BEBEBEBE
BEBEBEBEBFBFC1C1C0BEBCBABABCBFC1C1C0BEBDBDBDBDBDBDBDBDBDBBBBBBBABA ]%%
INFO: [Wed Jun 28 11:48:23 2006] 1601850.fm.ipl.BA6164 (77380)
INFO: [Wed Jun 28 11:49:53 2006] 1601854.fm.ipl.CA6164 (77382)
INFO: [Wed Jun 28 11:50:42 2006] 1601880.fm.ipl.DA6164 (77386)
INFO: [Wed Jun 28 11:53:11 2006] 1601850.fm.ipl.EA6164 (77388)
INFO: [Wed Jun 28 11:55:00 2006] BT-1601887 (77392)
INFO: [Wed Jun 28 11:55:23 2006] BT-1601888 (77395)
INFO: [Wed Jun 28 11:56:30 2006] smbprn.00000056 Taping-Packing_e.fm (77396)
INFO: [Wed Jun 28 12:30:39 2006] Microsoft Word - BB II-200b Ortsteile Mitte (77439)
INFO: [Wed Jun 28 12:33:57 2006] Microsoft Word - BB II-201b Ortsteil Moabit.doc (77442)
INFO: [Wed Jun 28 12:40:28 2006] Microsoft Word - BB XI-219 Ortsteil Friedenau.doc (77450)
INFO: [Wed Jun 28 12:43:29 2006] Microsoft Word - BB XI-237 Ortsteile Schöneberg und 
Tempelhof.doc (77453)
---snip---

That's mainly for saving the PS interpreter's error messages.

With CUPS 1.2, we will use notifications as well, but we are awaiting some more
bugfixes...

Helge

-- 
Helge Blischke
Softwareentwicklung
SRZ Berlin | Firmengruppe besscom
http://www.srz.de