Too much DEBUG info from MS 6.2.1

[jratike80]

We have compiled Mapserver 6.2.1 for Linux and the version info is as follows

MapServer version 6.2.1
OUTPUT=GIF OUTPUT=PNG OUTPUT=JPEG SUPPORTS=PROJ
SUPPORTS=GD SUPPORTS=AGG SUPPORTS=FREETYPE SUPPORTS=CAIRO
SUPPORTS=ICONV SUPPORTS=WMS_SERVER SUPPORTS=WMS_CLIENT
SUPPORTS=WFS_SERVER SUPPORTS=WFS_CLIENT SUPPORTS=WCS_SERVER
SUPPORTS=SOS_SERVER SUPPORTS=FASTCGI SUPPORTS=THREADS
SUPPORTS=GEOS INPUT=JPEG INPUT=OGR INPUT=GDAL INPUT=SHAPEFILE

This version writes whole lot of debug info into MS_ERRORFILE even if I do not have DEBUG line in the mapfile at all or if I have set it to DEBUG 0 or DEBUG OFF.

An example output from one WMS GetMap requers GROUP layer which is combined from 11 scale dependent layers follows. The same mapfile on MS 6.0 on Windows (MS4W) does not produce any output into the errorfile it there is no DEBUG row in the mapfile or if the debug level is set to 0 or OFF.

[Mon Jun 3 16:12:25 2013].799634 loadParams() QUERY_STRING: map=/test.map&REQUEST=GetMap&SERVICE=WMS&VERSION=1.1.1&WIDTH=1059&HEIGHT=776&LAYERS=group&TRANSPARENT=TRUE&FORMAT=image%2Fpng&BBOX=-302742.3606628045,6634887.305484046,1741121.9462003412,8132563.133742593&SRS=EPSG:3067&STYLES=
[Mon Jun 3 16:12:25 2013].801140 msLoadMap(): 0.001s
[Mon Jun 3 16:12:25 2013].802506 msLayerIsVisible(): Skipping layer (mml_taustakartta_2) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].802522 msLayerIsVisible(): Skipping layer (mml_taustakartta_3) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].802528 msLayerIsVisible(): Skipping layer (mml_taustakartta_4) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].802533 msLayerIsVisible(): Skipping layer (mml_taustakartta_5) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].802537 msLayerIsVisible(): Skipping layer (mml_taustakartta_6) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].802542 msLayerIsVisible(): Skipping layer (mml_taustakartta_7) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].802546 msLayerIsVisible(): Skipping layer (mml_taustakartta_8) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].802551 msLayerIsVisible(): Skipping layer (mml_taustakartta_9) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].802555 msLayerIsVisible(): Skipping layer (mml_taustakartta_10) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].802560 msLayerIsVisible(): Skipping layer (mml_taustakartta_11) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].802566 msLayerIsVisible(): Skipping layer (mml_taustakartta_2) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].802571 msLayerIsVisible(): Skipping layer (mml_taustakartta_3) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].802575 msLayerIsVisible(): Skipping layer (mml_taustakartta_4) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].802580 msLayerIsVisible(): Skipping layer (mml_taustakartta_5) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].802584 msLayerIsVisible(): Skipping layer (mml_taustakartta_6) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].802589 msLayerIsVisible(): Skipping layer (mml_taustakartta_7) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].802593 msLayerIsVisible(): Skipping layer (mml_taustakartta_8) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].802598 msLayerIsVisible(): Skipping layer (mml_taustakartta_9) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].802602 msLayerIsVisible(): Skipping layer (mml_taustakartta_10) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].802607 msLayerIsVisible(): Skipping layer (mml_taustakartta_11) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].802616 msDrawRasterLayerLow(mml_taustakartta_1): entering.
[Mon Jun 3 16:12:25 2013].802815 msResampleGDALToMap in effect: cellsize = 1932.163743
[Mon Jun 3 16:12:25 2013].803881 msDrawGDAL(mml_taustakartta_1): using RAW_WINDOW=76 93 1652 1501, dst=0,0,855,777
[Mon Jun 3 16:12:25 2013].803915 msDrawRasterLayerGDAL(): red,green,blue,alpha bands = 1,2,3,0
[Mon Jun 3 16:12:25 2013].847533 msDrawMap(): Layer 0 (mml_taustakartta_1), 0.045s
[Mon Jun 3 16:12:25 2013].847558 msLayerIsVisible(): Skipping layer (mml_taustakartta_2) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].847564 msLayerIsVisible(): Skipping layer (mml_taustakartta_3) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].847710 msLayerIsVisible(): Skipping layer (mml_taustakartta_4) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].847722 msLayerIsVisible(): Skipping layer (mml_taustakartta_5) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].847727 msLayerIsVisible(): Skipping layer (mml_taustakartta_6) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].847732 msLayerIsVisible(): Skipping layer (mml_taustakartta_7) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].847737 msLayerIsVisible(): Skipping layer (mml_taustakartta_8) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].847741 msLayerIsVisible(): Skipping layer (mml_taustakartta_9) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].847746 msLayerIsVisible(): Skipping layer (mml_taustakartta_10) because LAYER.MAXSCALE is too small for this MAP scale
[Mon Jun 3 16:12:25 2013].847751 msLayerIsVisible(): Skipping layer (mml_taustakartta_11) because LAYER.MAXSCALE is too small for this MAP scale

-Jukka Rahkonen-

[tbonfort]

These debug messages are there because you probably have a DEBUG level defined at the LAYER level. If this is the case, for me this is not a bug, so please close accordingly.

[jratike80]

Unfortunately that is not the case. I am using mapfiles which have been in production for about 4 years with Mapserver 5.x and 6.0 versions. I have debug lines on every layer but they are all commented # DEBUG 5 and I did a try by deleting DEBUG lines totally.

[tbonfort]

The debug code in question is here https://github.com/mapserver/mapserver/blob/branch-6-2/mapdraw.c#L625 and leaves little doubt that the debug message will only be printed if layer->debug is set. An to my knowledge, there have been no changes to the debug logging in 6.2 compared to 6.0.
I would check that you are effectively using the mapfile you think you are using, or that you have correctly done a "make clean && make" in case you have applied some patches to the 6.2 source code.

[jratike80]

Mapserver has been compiled by another person. From the documents I have he has first installed these on CentOS

yum install libpng-devel cairo-devel db4-devel
expat-devel fcgi-devel fontcon-fig-devel freetype-devel
gd-devel gd-progs giflib-devel gnutls kernel-devel
eyutils-libs-devel krb5-devel ksh libX11-devel libXau-devel
libcurl-devel lib-gcrypt-devel libidn-devel libjpeg-turbo-devel
libselinux-devel libsepol-devel libtiff-devel libxcb-devel
libxml2-devel libxslt-devel lldpad-libs openssl-devel pixman-devel
xorg-x11-proto-devel xz xz-lzma-compat zlib-devel

Then he has compiled programs in this order:
gdal, geos, proj, httpd, mapserver, mapcache, mod_fcgid
We have not made any own changes for the sources.

Config options for Mapserver were as follows:
./configure --prefix=$HOME/mapserver
--with-freetype=/usr
--with-png
--with-gif
--with-jpeg
--with-gd
--with-expat=/usr
--with-proj=$HOME/mapserver
--with-threads
--with-geos=$HOME/mapserver/bin/geos-config
--with-ogr=$HOME/gdal/bin/gdal-config
--with-gdal=$HOME/gdal/bin/gdal-config
--with-wfs
--with-wcs
--with-wmsclient
--with-wfsclient
--with-sos
--with-curl-config=/usr/bin/curl-config
--with-xml2-config=/usr/bin/xml2-config
--with-xslt=/usr
--with-cairo=/usr/lib64/pkgconfig/cairo.pc
--with-fastcgi=/usr
--with-apache-module
--with-apxs=$HOME/apache/bin/apxs
--with-apr-config=$HOME/apache/bin/apr-1-config

Then the Linux man did make;make install.

If this is not enough for giving a hint about why I keep on getting debug data I have whole lot of stuff in installation directories like config.log.

[dmorissette]

I agree with Thomas that you are likely not using the mapfile you think you are. Perhaps try to trim it down until you have the smallest possible testcase to reproduce the issue and then the source of the problem will become more obvious.

Another possibility might be that you have the MS_DEBUGLEVEL environment variable set in your environment, which is another way to turn on debug logs.

[jratike80]

I do believe that this is impossible but it does really happen for me. I made a totally new mapfile "fake.map" and placed DEBUG OFF into MAP level and also into LAYER level.

MAP
NAME ""
STATUS ON
MAXSIZE 5000
CONFIG "MS_ERRORFILE" "/users/wms/data/ms_errorfiles/fake2_error.txt"
EXTENT 19970 6597278 749676 7785300
SIZE 600 600
SHAPEPATH "/users/data/tmp/ms_tmp"
IMAGECOLOR 255 255 255
UNITS METERS
WEB
IMAGEPATH "/users/data/tmp/ms_tmp"
IMAGEURL "/users/data/tmp/ms_tmp"
METADATA
"ows_enable_request" "*"
"wms_srs" "EPSG:3067 EPSG:2393 EPSG:4326 EPSG:3857"
"wms_onlineresource" "http://fake.fi/cgi-bin/mapserv?"
"wms_title" "Fake service"
"wms_feature_info_mime_type" "text/html"
"wms_bbox_extended" "true"
END
END
PROJECTION
"init=epsg:3067"
END
DEBUG OFF
OUTPUTFORMAT
NAME 'AGG_Q'
MIMETYPE "image/png"
DRIVER "AGG/PNG"
EXTENSION "png"
IMAGEMODE RGB
FORMATOPTION "QUANTIZE_FORCE=ON"
FORMATOPTION "QUANTIZE_DITHER=OFF"
FORMATOPTION "QUANTIZE_COLORS=256"
END
LAYER
NAME "FAKE_FOR_DEBUG"
STATUS ON
DATA "/users/wms/data/vektorit/aluerajaukset/laani_v200"
TYPE LINE
UNITS METERS
SIZEUNITS PIXELS
TOLERANCE 3
DEBUG OFF
TOLERANCEUNITS PIXELS
METADATA
"wms_title" "FAKE_FOR_DEBUG"
"wms_srs" "EPSG:3067 EPSG:2393 EPSG:4326 EPSG:3857"
END
CLASS
NAME "AVI"
STYLE
COLOR 200 50 0
WIDTH 2
END
END
PROJECTION
"init=epsg:2393"
END
END
END

When I connect this new service for the first time the errorfile appears and starts to collect data

[Tue Jun 4 16:31:45 2013].496594 msLoadMap(): 0.001s
[Tue Jun 4 16:31:47 2013].48000 loadParams() QUERY_STRING: map=/users/wms/data/maps/fake.map&REQUEST=GetMap&SERVICE=WMS&VERSION=1.1.1&WIDTH=459&HEIGHT=346&LAYERS=FAKE_FOR_DEBUG&TRANSPARENT=TRUE&FORMAT=image%2Fpng&BBOX=-47905.83126004244,6648911.7385526495,743413.9083960592,7245418.557552674&SRS=EPSG:3067&STYLES=
[Tue Jun 4 16:31:47 2013].48469 msLoadMap(): 0.000s
[Tue Jun 4 16:31:47 2013].663738 loadParams() QUERY_STRING: map=/users/wms/data/maps/fake.map&REQUEST=GetMap&SERVICE=WMS&VERSION=1.1.1&WIDTH=459&HEIGHT=346&LAYERS=FAKE_FOR_DEBUG&TRANSPARENT=TRUE&FORMAT=image%2Fpng&BBOX=-473735.8436675745,6367898.410526628,1108903.6356446294,7560912.048526676&SRS=EPSG:3067&STYLES=
[Tue Jun 4 16:31:47 2013].664179 msLoadMap(): 0.000s
[Tue Jun 4 16:32:18 2013].152420 loadParams() QUERY_STRING: map=/users/wms/data/maps/fake.map&REQUEST=GetMap&SERVICE=WMS&VERSION=1.1.1&WIDTH=459&HEIGHT=346&LAYERS=FAKE_FOR_DEBUG&TRANSPARENT=TRUE&FORMAT=image%2Fpng&BBOX=-1363324.0477254144,5830007.868538167,1801954.9108989933,8216035.144538265&SRS=EPSG:3067&STYLES=

And a little bit more info: I can change the DEBUG level on the fly and get more info by editing the mapfile to have DEBUG 5. DEBUG 0 gathers less info but the minimum is what you can see from above. Looks like my server has a fixed minimum debug level but it is none of the standard levels. If I use DEBUG 1 in the mapfile I am getting also msSearchDiskTree messages. With DEBUB 0 I get only those QUERY_STRING lines.

[dmorissette]

Looks like you may have the MS_DEBUGLEVEL environment variable set somewhere: The QUERY_STRING debug statements should appear only if you set the MS_DEBUGLEVEL environment variable since they are generated before the mapfile is read.

Can you please confirm that you do not have the MS_DEBUGLEVEL environment variable set in your Apache config or in some boot scripts?

[jratike80]

Thanks Daniel, you were right from the beginning. Before closing I make a summary here and in the Mapserver users mailing list.

The very reason was that Linux server admin without experience on Mapserver copied httpd.conf from MS4W installation and removed a comment from here

uncomment the following lines to log MapServer errors to a file

#SetEnv MS_DEBUGLEVEL 3

Logging errors to a file feels like a good idea and not dangerous at all. However the comment is misleading and debug level 3 collects much more info than just errors. I believe that this setting it is unsuitable for most production system and I will write a note for Jeff McKenna and suggest to add another comment line for warning.

Mapserver documentation deals with debug in 4 places:
[1] Mapfile MAP http://www.mapserver.org/mapfile/map.html
[2] Mapfile LAYER http://www.mapserver.org/mapfile/layer.html
[3] Special debugging page http://www.mapserver.org/optimization/debugging.html
[4] RFC 28 page http://www.mapserver.org/development/rfc/ms-rfc-28.html#rfc28

After carefully reading the documentation I feel only moderately ashamed for not finding that the reason for my trouble was in MS_DEBUGLEVEL environment variable. Both [1] and [2] are telling about this only
"You can also set the debug level by using the “MS_DEBUGLEVEL” environment variable."
However, they have links for getting more info about debug mechanism. [1] has a link to [3] while [2] has a link to [4].

Documents [3] and [4] contain the same text about having set both MS_DEBUGLEVEL and DEBUG
" If a DEBUG value is also specified in the mapfile in some map or layer objects then the local value (in the mapfile) takes precedence over the value of the environment variable."

That is not totally true and it it also somehow documented that DEBUG will not always override MS_DEBUGLEVEL totally because
"This option also sets the debug level for any msDebug() call located outside of the context of a map or layer object, for instance for debug statements relating to initialization before a map is loaded. "

Conclusions:

• Ticket can be closed as invalid
• Link in document [2] could be changed to point to [3] instead of [4]
• [3] might be edited a bit "..takes precedence over the value of the environment variable for those objects..Debug info coming from outside of the context of a map or layer object cannot be turned off by having DEBUG OFF in the mapfile "
• There is a comment in the RFC [4] which would be useful to have also in the main debugging page
  "This option [setting MS_DEBUGLEVEL] is mostly useful when tuning applications by enabling timing/debug output before the map is loaded, to capture the full process initialization and map loading time, for instance."

From my experience the debugging document should strongly encourage to use layer or map level DEBUG for all regular needs instead of MS_DEBUGLEVEL.

[dmorissette]

May I suggest that you submit a pull request against the mapserver/docs repository with your suggested docs change? Thanks in advance.