[Geoserver-users] null value in log file

GeoServer GeoServer User
1

hi,

i got a question about the log file.

what does that mean ?

192.168.2.4 - - [02/05/2007:12:19:42 +0000] “GET /geoserver/wfs?VERSION=1.0.0&SERVICE=WFS&REQUEST=GetFeature&typename=topp:deud70________pi&bbox=7.059917449951172 ,51.49108352620136,7.085666656494141,51.50470902423732 HTTP/1.0” 200 39592
192.168.2.4 - - [02/05/2007:12:24:56 +0000] “GET /geoserver/wfs?VERSION=1.0.0&SERVICE=WFS&REQUEST=GetFeature&typename=topp:deud70________pi&bbox=7.068843841552734 ,51.490121572426,7.094593048095703,51.503747357988686 HTTP/1.0” 200 54397
null - - [02/05/2007:13:05:57 +0000] “GET /geoserver/wfs?VERSION=1.0.0&SERVICE=WFS&REQUEST=GetFeature&typename=topp:deud70________pi&bbox=8.032550811767578 ,51.391065489647175,8.084049224853515,51.41837215879149 HTTP/1.0” 200 562
null - - [02/05/2007:13:05:59 +0000] “GET /geoserver/wfs?VERSION=1.0.0&SERVICE=WFS&REQUEST=GetFeature&typename=topp:deud70________pi&bbox=8.037958145141601 ,51.422921685158144,8.089456558227539,51.450209333905384 HTTP/1.0” 200 562

the request always comes from 192.168.2.4…why are the last logs going to null ??

Regards,

Jan

2

jan w. ha scritto:

hi,

i got a question about the log file.

what does that mean ?

192.168.2.4 <http://192.168.2.4> - - [02/05/2007:12:19:42 +0000] "GET /geoserver/wfs?VERSION=1.0.0&SERVICE=WFS&REQUEST=GetFeature&typename=topp:deud70________pi&bbox=7.059917449951172 ,51.49108352620136,7.085666656494141,51.50470902423732 HTTP/1.0" 200 39592
192.168.2.4 <http://192.168.2.4> - - [02/05/2007:12:24:56 +0000] "GET /geoserver/wfs?VERSION=1.0.0&SERVICE=WFS&REQUEST=GetFeature&typename=topp:deud70________pi&bbox=7.068843841552734 ,51.490121572426,7.094593048095703,51.503747357988686 HTTP/1.0" 200 54397
null - - [02/05/2007:13:05:57 +0000] "GET /geoserver/wfs?VERSION=1.0.0&SERVICE=WFS&REQUEST=GetFeature&typename=topp:deud70________pi&bbox=8.032550811767578 ,51.391065489647175,8.084049224853515,51.41837215879149 HTTP/1.0" 200 562
null - - [02/05/2007:13:05:59 +0000] "GET /geoserver/wfs?VERSION=1.0.0&SERVICE=WFS&REQUEST=GetFeature&typename=topp:deud70________pi&bbox=8.037958145141601 ,51.422921685158144,8.089456558227539,51.450209333905384 HTTP/1.0" 200 562

the request always comes from 192.168.2.4...why are the last logs going to null ??

Hum.... I have no idea? Is that Geoserver log? Does not look like it.
Seems more like a container log to me?

cheers
Andrea

3

I have a similar problem with null log entries. I am running GeoServer 1.4.1
on Windows, using IIS as the web server and Jetty as the servlet container.
However, the problem is indeed in the GeoServer request log.

I think some of what makes your response look strange is that line wrapping
is making one line in the log look like 3 lines in your post. My log is
more concise, so it may be easier for other users to read. Here is a few
line exerpt from the file 2007-05-18.request.log:

null - - [18/05/2007:20:46:54 +0000] "POST /geoserver/wfs HTTP/1.1" 200
12053
null - - [18/05/2007:20:48:18 +0000] "POST /geoserver/wfs HTTP/1.1" 200
12575
null - - [18/05/2007:20:50:10 +0000] "POST /geoserver/wfs HTTP/1.1" 200
12589
66.238.192.50 - - [18/05/2007:20:52:00 +0000] "POST /geoserver/wfs
HTTP/1.1" 200 1745
66.238.192.50 - - [18/05/2007:21:00:44 +0000] "POST /geoserver/wfs
HTTP/1.1" 200 2074

Like the previous poster, the requests are always coming from the same IP
address (66.238.192.50).

This produces a serious bug for my application. We are using GeoServer to
provide data to a limited group of customers, thus we limit our service to
just a few blocks of IP addresses. When the "null" IP address is logged,
the client application making the GeoServer request gets an error that looks
like this:

Error returned from http://ogc.wsiwxconnect.com:7777/geoserver/wfs
500 Server closed connection without sending any data back
500 Server closed connection without sending any data back

I suspect that the error is due to our system configuration, in which we
only allow responses to certain known blocks of IP addresses.

We are currently unable to reliably reproduce the problem, but it happens
fairly frequently (multiple times per day). If anyone has insights into
what causes this problem, or even how to reproduce it consistantly, it would
be a great help.

Yours,
Steve
---------

i got a question about the log file.
what does that mean ?

192.168.2.4 - - [02/05/2007:12:19:42 +0000] "GET /geoserver/wfs?VERSION=
1.0.0&SERVICE=WFS&REQUEST=GetFeature&typename=topp:deud70________pi&bbox=7.059917449951172
,51.49108352620136,7.085666656494141,51.50470902423732 HTTP/1.0" 200 39592
192.168.2.4 - - [02/05/2007:12:24:56 +0000] "GET /geoserver/wfs?VERSION=
1.0.0&SERVICE=WFS&REQUEST=GetFeature&typename=topp:deud70________pi&bbox=7.068843841552734
,51.490121572426,7.094593048095703,51.503747357988686 HTTP/1.0" 200 54397
null - - [02/05/2007:13:05:57 +0000] "GET /geoserver/wfs?VERSION=
1.0.0&SERVICE=WFS&REQUEST=GetFeature&typename=topp:deud70________pi&bbox=8.032550811767578
,51.391065489647175,8.084049224853515,51.41837215879149 HTTP/1.0" 200 562
null - - [02/05/2007:13:05:59 +0000] "GET /geoserver/wfs?VERSION=
1.0.0&SERVICE=WFS&REQUEST=GetFeature&typename=topp:deud70________pi&bbox=8.037958145141601
,51.422921685158144,8.089456558227539,51.450209333905384 HTTP/1.0" 200 562

the request always comes from 192.168.2.4...why are the last logs going to
null ??

Regards,

Jan

--
View this message in context: http://www.nabble.com/null-value-in-log-file-tf3680605.html#a10767274
Sent from the GeoServer - User mailing list archive at Nabble.com.

4

hi,

my requests come from on php script running on an IIS, seems to be a problem with IIS?!
i could never reproduce the behaviour…

Regards,

Jan

2007/5/23, Steve Marshall < smarshall@anonymised.com>:

I have a similar problem with null log entries. I am running GeoServer on
Windows, using IIS as the web server and Jetty as the servlet container.
However, the problem is indeed in the GeoServer request log.

I think some of what makes your response look strange is that line wrapping
is making one line in the log look like 3 lines in your post. My log is
more concise, so it may be easier for other users to read. Here is a few
line exerpt from the file 2007-05-18.request.log:

null - - [18/05/2007:20:46:54 +0000] “POST /geoserver/wfs HTTP/1.1” 200
12053
null - - [18/05/2007:20:48:18 +0000] “POST /geoserver/wfs HTTP/1.1” 200
12575
null - - [18/05/2007:20:50:10 +0000] “POST /geoserver/wfs HTTP/1.1” 200
12589
66.238.192.50 - - [18/05/2007:20:52:00 +0000] “POST /geoserver/wfs
HTTP/1.1” 200 1745
66.238.192.50 - - [18/05/2007:21:00:44 +0000] “POST /geoserver/wfs
HTTP/1.1” 200 2074

Like the previous poster, the requests are always coming from the same IP
address (66.238.192.50).

This produces a serious bug for my application. We are using GeoServer to
provide data to a limited group of customers, thus we limit our service to
just a few blocks of IP addresses. When the “null” IP address is logged,
the client application making the GeoServer request gets an error that looks
like this:

Error returned from http://ogc.wsiwxconnect.com:7777/geoserver/wfs
500 Server closed connection without sending any data back
500 Server closed connection without sending any data back

I suspect that the error is due to our system configuration, in which we
only allow responses to certain known blocks of IP addresses.

We are currently unable to reliably reproduce the problem, but it happens
fairly frequently (multiple times per day). If anyone has insights into
what causes this problem, or even how to reproduce it consistantly, it would
be a great help.

Yours,
Steve

i got a question about the log file.
what does that mean ?

192.168.2.4 - - [02/05/2007:12:19:42 +0000] “GET /geoserver/wfs?VERSION=
1.0.0&SERVICE=WFS&REQUEST=GetFeature&typename=topp:deud70________pi&bbox=7.059917449951172
,51.49108352620136,7.085666656494141,51.50470902423732 HTTP/1.0” 200 39592
192.168.2.4 - - [02/05/2007:12:24:56 +0000] “GET /geoserver/wfs?VERSION=
1.0.0&SERVICE=WFS&REQUEST=GetFeature&typename=topp:deud70________pi&bbox=7.068843841552734
,51.490121572426,7.094593048095703,51.503747357988686 HTTP/1.0” 200 54397
null - - [02/05/2007:13:05:57 +0000] “GET /geoserver/wfs?VERSION=
1.0.0&SERVICE=WFS&REQUEST=GetFeature&typename=topp:deud70________pi&bbox=8.032550811767578
,51.391065489647175,8.084049224853515,51.41837215879149 HTTP/1.0” 200 562
null - - [02/05/2007:13:05:59 +0000] “GET /geoserver/wfs?VERSION=
1.0.0&SERVICE=WFS&REQUEST=GetFeature&typename=topp:deud70________pi&bbox=8.037958145141601
,51.422921685158144,8.089456558227539,51.450209333905384 HTTP/1.0” 200 562

the request always comes from 192.168.2.4…why are the last logs going to
null ??

Regards,

Jan

–
View this message in context: http://www.nabble.com/null-value-in-log-file-tf3680605.html#a10767274
Sent from the GeoServer - User mailing list archive at Nabble.com.

This SF.net email is sponsored by DB2 Express
Download DB2 Express C - the FREE version of DB2 express and take
control of your XML. No limits. Just data. Click to get it now.
http://sourceforge.net/powerbar/db2/

Geoserver-users mailing list
Geoserver-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/geoserver-users

5

Steve Marshall ha scritto:

null - - [18/05/2007:20:46:54 +0000] "POST /geoserver/wfs HTTP/1.1" 200
12053 null - - [18/05/2007:20:48:18 +0000] "POST /geoserver/wfs HTTP/1.1" 200
12575 null - - [18/05/2007:20:50:10 +0000] "POST /geoserver/wfs HTTP/1.1" 200
12589 66.238.192.50 - - [18/05/2007:20:52:00 +0000] "POST /geoserver/wfs
HTTP/1.1" 200 1745 66.238.192.50 - - [18/05/2007:21:00:44 +0000] "POST /geoserver/wfs
HTTP/1.1" 200 2074

Like the previous poster, the requests are always coming from the same IP
address (66.238.192.50).

These logs are not generated by Geoserver, but by Jetty, the container
that we ship by default with Geoserver (I never noticed them, just went
looking for them since you told me you're using IIS, so I assumed you went for the easy to use installer instead of deploying in your own
web container). Can you try using another one, such as Tomcat, as see if this solves the problem?

Cheers
Andrea

6

jan w. ha scritto:

hi,

my requests come from on php script running on an IIS, seems to be a problem with IIS?!
i could never reproduce the behaviour....

Ah, one thing you could do, if the problem is relatively easy to reproduce, is to run Geoserver interactively, instead of running
it as a service, and copy the stack traces you see from the console
window.

Cheers
Andrea

7

my requests come from on php script running on an IIS, seems to be a
problem with IIS?!
i could never reproduce the behaviour....

Ah, one thing you could do, if the problem is relatively easy to
reproduce, is to run Geoserver interactively, instead of running
it as a service, and copy the stack traces you see from the console
window.

Andrea,
Sounds like a good sugestion. Unfortunately, the problem is actually rather
difficult to reproduce (the cause is unknown). Therefore, watching the
console is like looking for a needle in a haystack. I tried to startup
GeoServer in a console window, redirecting stdout and stderr to a log file
so I could search through loads of console information at my leisure. I did
the output redirection in the standard Linux way, i.e. by appending" >
log-file 2>&1" to the command. I believe this is also valid syntax for
Windows. However, when started this way, GeoServer seems to be unresponsive
after issuing this log message:

14297 [FINE] org.geotools.data.jdbc.ConnectionPool - Getting available
connection.

Any thoughts why this would happen? Are there any services associated with
Jetty I should restart to make changes take effect?

Thanks for any insights,
Steve

--
View this message in context: http://www.nabble.com/null-value-in-log-file-tf3680605.html#a10789565
Sent from the GeoServer - User mailing list archive at Nabble.com.

8

Steve Marshall ha scritto:

Any thoughts why this would happen? Are there any services associated with
Jetty I should restart to make changes take effect?

Not really, but I think I have a better suggestion.
Go in the Geoserver control panel, server section, and tell it to save
the logs to file, set a "CONFIG" logging level, submit, apply, and save.
To make sure the file is generated, kill and restart Geoserver, then
you should see a log directory in the Geoserver data dir with a Geoserver.log file. The file growth will be jumpy, because we buffer
logs in memory and dump them every few kb to avoid slowing it down
too much, but once you have reproduced the issue, just stop
geoserver, and send me the log (by private mail, since the
mailing list won't accept attachments).

Cheers
Andrea

9

Marshall, Steve ha scritto:

Andrea,

Thanks for your diagnosis of this error:

Caused by: java.net.SocketException: Connection reset
  at java.net.SocketInputStream.read(SocketInputStream.java:168)
  at
java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
  at
java.io.BufferedInputStream.read(BufferedInputStream.java:237)
  at org.postgresql.core.PGStream.ReceiveChar(PGStream.java:256)
  at
org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImp
l.java:1163)
  at
org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:
188)
  ... 50 more

See that Caused by: java.net.SocketException: Connection reset, near the
end? Postgres for some reason is severing the connections Geoserver has.
Unfortunately our connection pool code is very old (needs replacement),
and does not check for expired connections.
---
Regarding your suggestion:
Can you check the postgis configuration and see if you can allow
connections not to have a limited life span?

...There is not a configuration parameter in PostgreSQL to set the
maximum life span of a connection. There are timeouts on other
operations, like how long a single statement can run (statement_timeout)
or how long it can take to authenticate a connection
(authenticate_timeout), but these are not related to this situtation.

There are some parameters related to keeping an idle connection from
being dropped . These involve overriding the system defaults for
sending TCP KEEPALIVE messages on an otherwise idle socket connection.
However, the tcp_keepalive options were introduced in PostgreSQL 8.1,
and I am using PostgreSQL 8.0 as the backend for GeoServer, so playing
with the tcp_keepalive parameters is not currently an option for me.

The default tcp_keepalive parameters on the database server indicate
that a connection will be dropped after about 2 hours and 12 minutes of
idleness, so they explain why the connection gets closed if it is idle
overnight.

The tcp_keepalive parameters on the database server are:

Tcp_keepalive_intvl = 75
Tcp_keepalive_probes = 9
Tcp_keepalive_timeout = 7200

These parameters mean, start sending keep alive after 7200 seconds (2
hours). Send up to 9 keep alive messages, one every 75 seconds. If no
response to any of the keepalives, drop the connection.

I'll look into other database configuration options to keep the
connection open, but I'm not too optimistic about them. Even if I get
something working to keep connections from timing out, it would only be
a partial solution. There are other valid reasons why a connection
might be lost. For example, I have a two database systems behind the
GeoServer systems. If the primary database goes down, the secondary
will take over and start responding to the hostname formerly used by the
primary. However, the failure of the primary will invalidate the
connection held by GeoServer, so making the failover work correctly
requires client applications to reconnect to the database in response to
a lost connection.

It seems like GeoServer is not too far from having this capability.
GeoServer seems to do all the right reconnection work, but only as the
response to a failed query. If GeoServer could be made to reissue the
SQL command that caused the need to reconnect, I think this problem
would be solved.

Lost connection error handling could be made more robust if loss of
connectivity errors could be handled separately from other database
errors. I'm not sure how JDBC organizes database exceptions, but there
are two big classes of database errors: loss of connectivity to the
database, and errors caused by the commands sent to the database.
Essentially for lost connections, there is nothing necessarily wrong
with the SQL command, so it should be reexecuted once the connection is
reestablished. For other errors, the SQL is likely suspect, so
reexecuting the command feels like the wrong response.

I'm not sure where this work falls in the priority of other GeoServer
tasks, but it strikes me as a very critical issue for making GeoServer
work reliably in operational environments, where consistant availability
is a requirement. Is there some place to request this feature as an
enhancment to GeoServer?

Thanks for your assistance on this. If you have any other helpful
suggestions, or think I've misinterpretted something, please let me
know.

You're welcomed.
I sent this mail to the users mailing list too so that other people
can share your concerns, which are quite appropriate.
Yeah, usually connection pool libraries have the ability to check
connection validity before providing one, but unfortunately our
custom made old rusty pool cannot.
I can try to check, usually stuff like DBCP wants a query that
it may fire to assess a connection liveliness before returning
it. But yeah, I agree this is a serious issues.

Please, open a report on jira.codehaus.org against Geoserver,
and schedule it for 1.5.2 (1.5.1rc1 will be out of the door Monday,
so I don't think we'll manage to fix this unless we do find
a one liner solution).

Cheers
Andrea