Unverified Commit 86a4db8e authored by User expired's avatar User expired
Browse files

improved request/response trace logging (using separate threads and introduced a config value)

parent b35cdf73
Upcoming version:
-----------------
- improved request/response trace logging (using separate threads and introduced a config value) (Nikolaus Krismer)
- updating gradle wrapper (to version 4.2) (Nikolaus Krismer)
- fixed broken tests (fixed property visibility in ConfigDataset) (Nikolaus Krismer)
- upgrading leaflet to latest version 1.2.0 (Nikolaus Krismer)
......
......@@ -19,6 +19,7 @@ Web configuration
* useCache: Enables isochrone caching (useful if identical isochrones are requested multiple times) and incremental isochrone calculation from cached results.
* useCoverageMask: Enables masking of the isochrone result (non-reachable area will be darkened instead of reachable one).
* useIsochroneStatistics: Prints statistics such as database query count and isochrone timings to the log file if enabled
* useJson2DiskSerializeation: If this flag is set to true, then all requests and responses from/to the server will also be saved to disk (in build/requests and build/responses). Allowed values are "true", "false, "on", "off" as well as "merged" and "separate".
* useMultiGeometries: Replaces single LineStrings with a MultLineString (same for Point and MultiPoint) before sending geoJson data.
* useStationsForCoverage: include public transportation stations into coverage computation, even if the station can be reached just in time (altough there would be no time to walk around in the station)
......@@ -59,6 +60,7 @@ The following configuration illustrates the default configuration.
<entry key="useCache">false</entry>
<entry key="useCoverageMask">true</entry>
<entry key="useIsochroneStatistics">false</entry>
<entry key="useJson2DiskSerializeation">false</entry>
<entry key="useMultiGeometries">true</entry>
<!-- When enabled, this shows a small coverage area around each
......
......@@ -20,6 +20,7 @@ import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import at.uibk.dbis.isomap.output.OutputType;
import at.uibk.dbis.isomap.web.api.JsonSerializerFormat;
import it.geosolutions.geoserver.rest.GeoServerRESTManager;
import it.geosolutions.geoserver.rest.GeoServerRESTPublisher;
import it.geosolutions.geoserver.rest.GeoServerRESTReader;
......@@ -38,6 +39,20 @@ public final class ConfigWeb {
private static final int PREFIX_MAX_LENGTH = 4;
private static ConfigWeb instance = null;
public static class JsonSerializerFormatTransformer extends TypeTransformer<String, JsonSerializerFormat> {
@Override
public JsonSerializerFormat transform(final String str) {
if (str.equalsIgnoreCase("false")) {
return JsonSerializerFormat.OFF;
}
if (str.equalsIgnoreCase("true") || str.equalsIgnoreCase("on")) {
return JsonSerializerFormat.MERGED;
}
return JsonSerializerFormat.valueOf(str.toUpperCase(Locale.ENGLISH));
}
}
public static class OutputTypeTransformer extends TypeTransformer<String, OutputType> {
@Override
public OutputType transform(final String str) {
......@@ -78,6 +93,12 @@ public final class ConfigWeb {
@PropertyValue("useIsochroneStatistics")
private Boolean useIsochroneStatistics;
@NotNull
@DefaultValue("false")
@PropertyValue("useJson2DiskSerializeation")
@TypeTransformers(JsonSerializerFormatTransformer.class)
private JsonSerializerFormat useJson2DiskSerializeation;
@NotNull
@DefaultValue("true")
@PropertyValue("useMultiGeometries")
......@@ -184,6 +205,10 @@ public final class ConfigWeb {
return (useIsochroneStatistics == null) ? Boolean.FALSE : useIsochroneStatistics.booleanValue();
}
public JsonSerializerFormat useJson2DiskSerializeation() {
return useJson2DiskSerializeation;
}
public boolean useJts() {
return outputType == OutputType.JTS;
}
......
package at.uibk.dbis.isomap.web.api;
import com.fasterxml.jackson.core.JsonProcessingException;
import com.fasterxml.jackson.databind.ObjectWriter;
import com.fasterxml.jackson.databind.SerializationFeature;
import java.io.BufferedWriter;
import java.io.File;
import java.io.FileOutputStream;
import java.io.IOException;
import java.io.OutputStreamWriter;
import java.io.Writer;
import java.nio.charset.StandardCharsets;
import java.time.LocalDateTime;
import java.util.Locale;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.geojson.FeatureCollection;
import at.uibk.dbis.isomap.config.ConfigWeb;
import at.uibk.dbis.isomap.service.dto.IRequest;
import at.uibk.dbis.isomap.service.dto.IResponse;
import at.uibk.dbis.isomap.service.dto.ResponseIsochrone;
import at.uibk.dbis.isomap.web.resolver.DtoResolver;
class AbstractJsonApi {
private static final Logger LOGGER = LogManager.getLogger(AbstractJsonApi.class);
private static final String EXTENSION_JSON = ".json";
private static final String EXTENSION_GEOJSON = EXTENSION_JSON;
private static final JsonSerializerFormat JSON2DISK_SERIALIZATION;
private static final ObjectWriter MAPPER;
protected enum TraceDirectory {
REQUEST("build/requests"),
RESPONSE("build/responses");
private final String dir;
private TraceDirectory(final String dir) {
this.dir = dir;
}
public String getDirectory() {
return dir;
}
}
static {
JSON2DISK_SERIALIZATION = ConfigWeb.getInstance().useJson2DiskSerializeation();
MAPPER = DtoResolver.MAPPER.copy()
.disable(SerializationFeature.FAIL_ON_EMPTY_BEANS)
.writerWithDefaultPrettyPrinter();
}
// Protected static methods
protected static String filterId(final String defaultPrefix, final String id) {
String result = (id == null) ? null : id.replaceAll("-", "_").replaceAll("['\"\\\\(){}\\[\\].;&öäüÖÄÜß]", "");
if (result == null || result.trim().length() <= 0) {
result = defaultPrefix + System.currentTimeMillis();
}
return result.toLowerCase(Locale.ENGLISH);
}
protected static void writeRequestTrace(final IRequest request) {
if (request == null) {
throw new NullPointerException("Can not write null request!");
}
if (JSON2DISK_SERIALIZATION == JsonSerializerFormat.OFF) {
return;
}
final Thread t = new Thread(() -> {
final String str;
try {
str = MAPPER.writeValueAsString(request);
} catch (final JsonProcessingException e) {
LOGGER.warn("Can not write feature collection to file");
LOGGER.catching(e);
return;
}
final String dir = TraceDirectory.REQUEST.getDirectory();
final LocalDateTime tStamp = LocalDateTime.now();
final String filename = request.getClass().getSimpleName().toLowerCase(Locale.ENGLISH).replaceFirst("request", "");
write2TraceFile(dir, str, tStamp, filename, EXTENSION_JSON);
});
t.start();
}
protected static void writeResponseTrace(final IResponse response) {
if (response == null) {
throw new NullPointerException("Can not write null response!");
}
if (JSON2DISK_SERIALIZATION == JsonSerializerFormat.OFF) {
return;
}
final Thread t = new Thread(() -> {
final String str;
try {
str = MAPPER.writeValueAsString(response);
} catch (final JsonProcessingException e) {
LOGGER.warn("Can not write feature collection to file");
LOGGER.catching(e);
return;
}
final String dir = TraceDirectory.RESPONSE.getDirectory();
final LocalDateTime tStamp = LocalDateTime.now();
final String filename = response.getClass().getSimpleName().toLowerCase(Locale.ENGLISH).replaceFirst("response", "");
write2TraceFile(dir, str, tStamp, filename, EXTENSION_JSON);
if (response instanceof ResponseIsochrone) {
final ResponseIsochrone iResponse = ((ResponseIsochrone) response);
write2TraceFile(dir, iResponse.getGeoJsonCoverage(), tStamp, filename + "-coverage");
write2TraceFile(dir, iResponse.getGeoJsonEdges(), tStamp, filename + "-edges");
write2TraceFile(dir, iResponse.getGeoJsonNodes(), tStamp, filename + "-nodes");
}
});
t.start();
}
// Private static methods
private static void write2TraceFile(final String dir, final FeatureCollection fc, final LocalDateTime tStamp, final String filename) {
try {
write2TraceFile(dir, MAPPER.writeValueAsString(fc), tStamp, filename, EXTENSION_GEOJSON);
} catch (final JsonProcessingException e) {
LOGGER.warn("Can not write feature collection to file");
LOGGER.catching(e);
}
}
private static void write2TraceFile(final String dir, final String str, final LocalDateTime tStamp, final String filename, final String extension) {
if (str == null) {
throw new NullPointerException("Can not write null content to file!");
}
if (str.isEmpty()) {
return;
}
final boolean separateDirs = (JSON2DISK_SERIALIZATION == JsonSerializerFormat.SEPARATE);
final String fDir = (separateDirs) ? (dir + File.separator + filename) : dir;
final File resultDir = new File(fDir);
if (resultDir.mkdirs()) {
LOGGER.trace("Created trace directory \"{}\"", dir);
}
final String tStampStr = tStamp.toString();
final String fName = (separateDirs) ? (tStampStr + extension) : (tStampStr + "_" + filename + extension);
final File resultFile = new File(resultDir, fName);
final String absName = resultFile.getAbsolutePath();
try {
resultFile.createNewFile();
} catch (final IOException e) {
LOGGER.trace("Can not create trace file \"{}\"", absName);
return;
}
try (Writer out = new BufferedWriter(new OutputStreamWriter(new FileOutputStream(resultFile, false), StandardCharsets.UTF_8))) {
LOGGER.trace(" writing trace file \"{}\"", absName);
out.write(str);
out.flush();
} catch (final IOException e) {
LOGGER.trace("Can not write to trace file \"{}\"", absName);
LOGGER.catching(e);
}
}
}
package at.uibk.dbis.isomap.web.api;
import java.util.Locale;
public final class ApiHelper {
private ApiHelper() { }
public static String filterId(final String defaultPrefix, final String id) {
String result = (id == null) ? null : id.replaceAll("-", "_").replaceAll("['\"\\\\(){}\\[\\].;&öäüÖÄÜß]", "");
if (result == null || result.trim().length() <= 0) {
result = defaultPrefix + System.currentTimeMillis();
}
return result.toLowerCase(Locale.ENGLISH);
}
}
......@@ -25,7 +25,7 @@ import at.uibk.dbis.isomap.web.IllegalRequestException;
import at.uibk.dbis.isomap.web.resolver.ServiceResolver;
@Path("/isochrone")
public class JsonRestApi {
public class JsonRestApi extends AbstractJsonApi {
private static final Logger LOGGER = LogManager.getLogger(JsonRestApi.class.getName());
private static final String DEFAULT_CLIENTID_PREFIX = "rest_";
private static final Set<String> CURRENTLY_EXECUTED_CLIENT_IDS = new HashSet<>(5);
......@@ -35,7 +35,7 @@ public class JsonRestApi {
@GET
@Produces(MediaType.APPLICATION_JSON)
public ResponseIsochrone getIsochroneJson(@HeaderParam("Entity") final String jsonEntity, @HeaderParam("ClientId") final String cId) {
final String clientId = ApiHelper.filterId(DEFAULT_CLIENTID_PREFIX, cId);
final String clientId = filterId(DEFAULT_CLIENTID_PREFIX, cId);
LOGGER.debug("REST: Message from client \"{}\": {}", clientId, ""); // request);
synchronized (clientId) {
......@@ -62,13 +62,14 @@ public class JsonRestApi {
final long timeServiceCreation = System.currentTimeMillis();
LOGGER.debug(" service creation time: {}msec", timeServiceCreation - timeBegin);
ResponseIsochrone r = null;
ResponseIsochrone response = null;
try {
r = service.onJsonMessage(clientId, serviceResolver.getRequest());
final RequestIsochrone request = serviceResolver.getRequest();
writeRequestTrace(request);
response = service.onJsonMessage(clientId, request);
writeResponseTrace(response);
ConfigClient.removeClient(clientId);
} catch (final IllegalArgumentException e) {
throw getJsonException(e.getMessage(), HttpStatus.SC_INTERNAL_SERVER_ERROR);
} catch (final ServiceException e) {
} catch (final IllegalArgumentException | ServiceException e) {
throw getJsonException(e.getMessage(), HttpStatus.SC_INTERNAL_SERVER_ERROR);
} finally {
CURRENTLY_EXECUTED_CLIENT_IDS.remove(clientId);
......@@ -77,7 +78,7 @@ public class JsonRestApi {
final long timeResponseCreation = System.currentTimeMillis();
LOGGER.debug(" response creation time: {}msec", timeResponseCreation - timeServiceCreation);
return r;
return response;
}
// Private methods
......
package at.uibk.dbis.isomap.web.api;
public enum JsonSerializerFormat {
OFF,
MERGED,
SEPARATE;
}
......@@ -2,15 +2,9 @@ package at.uibk.dbis.isomap.web.api;
import com.fasterxml.jackson.core.JsonProcessingException;
import java.io.BufferedWriter;
import java.io.File;
import java.io.FileOutputStream;
import java.io.IOException;
import java.io.OutputStreamWriter;
import java.io.Writer;
import java.nio.ByteBuffer;
import java.nio.charset.Charset;
import java.nio.charset.StandardCharsets;
import java.util.Set;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
......@@ -32,7 +26,6 @@ import org.apache.commons.jcs.JCS;
import org.apache.commons.jcs.access.CacheAccess;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.geojson.FeatureCollection;
import at.uibk.dbis.isomap.config.ConfigClient;
import at.uibk.dbis.isomap.service.IService;
......@@ -41,14 +34,13 @@ import at.uibk.dbis.isomap.service.ServiceException;
import at.uibk.dbis.isomap.service.dto.IRequest;
import at.uibk.dbis.isomap.service.dto.IResponse;
import at.uibk.dbis.isomap.service.dto.ResponseError;
import at.uibk.dbis.isomap.service.dto.ResponseIsochrone;
import at.uibk.dbis.isomap.web.IllegalRequestException;
import at.uibk.dbis.isomap.web.InternalSocketException;
import at.uibk.dbis.isomap.web.resolver.DtoResolver;
import at.uibk.dbis.isomap.web.resolver.ServiceResolver;
@ServerEndpoint("/websocket")
public class JsonWebsocket {
public class JsonWebsocket extends AbstractJsonApi {
private static final Logger LOGGER = LogManager.getLogger(JsonWebsocket.class.getName());
private static final String CACHE_IDENTIFIER_SESSIONS = "sessions";
private static final Charset CONTENT_CHARSET = Charset.forName("UTF-8");
......@@ -58,14 +50,6 @@ public class JsonWebsocket {
private static final int RESPONSE_ZLIB_BUFFER_SIZE = 1024;
private static final CacheAccess<String, Session> SESSIONS;
static {
SESSIONS = JCS.getInstance(CACHE_IDENTIFIER_SESSIONS);
}
public static Session getSession(final String clientId) {
return SESSIONS.get(clientId);
}
// Private inner helper class
private static final class JsonResponseSender<S extends IService<T, U>, T extends IRequest, U extends IResponse> implements Runnable {
......@@ -87,21 +71,14 @@ public class JsonWebsocket {
final S service = serviceResolver.getService();
final long timeServiceCreation = System.currentTimeMillis();
LOGGER.debug(" service creation time: {}msec", timeServiceCreation - timeBegin);
final U response = service.onJsonMessage(clientId, serviceResolver.getRequest());
final T request = serviceResolver.getRequest();
writeRequestTrace(request);
final U response = service.onJsonMessage(clientId, request);
final long timeResponseCreation = System.currentTimeMillis();
LOGGER.debug(" response creation time: {}msec", timeResponseCreation - timeServiceCreation);
str = writeResponse(response);
writeResponseTrace(response);
LOGGER.debug(" response writing time: {}msec", System.currentTimeMillis() - timeResponseCreation);
if (LOGGER.isTraceEnabled()) {
writeToTmpFile(str);
if (response instanceof ResponseIsochrone) {
final ResponseIsochrone iResponse = ((ResponseIsochrone) response);
writeToTmpFile(iResponse.getGeoJsonCoverage(), "coverage");
writeToTmpFile(iResponse.getGeoJsonEdges(), "edges");
writeToTmpFile(iResponse.getGeoJsonNodes(), "nodes");
}
}
} catch (final InternalSocketException | ServiceException e) {
LOGGER.catching(e);
str = writeResponseError(serviceResolver, e);
......@@ -109,48 +86,13 @@ public class JsonWebsocket {
sendToClient(session, compressData(str));
}
private static void writeToTmpFile(final String str) {
writeToTmpFile(str, ".json");
}
private static void writeToTmpFile(final FeatureCollection fc, final String type) {
try {
writeToTmpFile(DtoResolver.MAPPER.writeValueAsString(fc), "-" + type + ".geojson");
} catch (final JsonProcessingException e) {
LOGGER.warn("Can not write feature collection to tmp file");
LOGGER.catching(e);
}
}
private static void writeToTmpFile(final String str, final String extension) {
final File resultFile;
try {
resultFile = File.createTempFile("isochrone-web-", extension);
} catch (final IOException e) {
LOGGER.trace("Can create temporary file");
return;
}
final String fName = resultFile.getAbsolutePath();
try (Writer out = new BufferedWriter(new OutputStreamWriter(new FileOutputStream(resultFile, false), StandardCharsets.UTF_8))) {
LOGGER.trace(" writing tmp file \"{}\"", fName);
out.write(str);
out.flush();
} catch (final IOException e) {
LOGGER.trace("Can not write to temporary file \"{}\"", fName);
LOGGER.catching(e);
} finally {
resultFile.deleteOnExit();
}
}
}
// Static block
static {
EXECUTOR = Executors.newFixedThreadPool(NUM_ASYNC_THREADS);
SESSIONS = JCS.getInstance(CACHE_IDENTIFIER_SESSIONS);
}
// Public static methods
......@@ -159,11 +101,15 @@ public class JsonWebsocket {
return EXECUTOR;
}
public static Session getSession(final String clientId) {
return SESSIONS.get(clientId);
}
// Websocket methods
@OnClose
public void onClose(final Session session, final CloseReason closeReason) {
final String clientId = ApiHelper.filterId(DEFAULT_CLIENTID_PREFIX, session.getId());
final String clientId = filterId(DEFAULT_CLIENTID_PREFIX, session.getId());
SESSIONS.remove(clientId);
final boolean taskKilled = ConfigClient.removeClient(clientId);
......@@ -176,14 +122,14 @@ public class JsonWebsocket {
@OnError
public void onError(final Session session, final Throwable throwable) {
final String clientId = ApiHelper.filterId(DEFAULT_CLIENTID_PREFIX, session.getId());
final String clientId = filterId(DEFAULT_CLIENTID_PREFIX, session.getId());
LOGGER.warn("Websocket: Error for client \"{}\"", clientId);
throwable.printStackTrace();
}
@OnMessage
public <S extends IService<T, U>, T extends IRequest, U extends IResponse> void onMessage(final Session session, final String message) {
final String clientId = ApiHelper.filterId(DEFAULT_CLIENTID_PREFIX, session.getId());
final String clientId = filterId(DEFAULT_CLIENTID_PREFIX, session.getId());
LOGGER.debug("Websocket: Message from client \"{}\": {}", clientId, message);
ServiceResolver<S, T, U> resolver = null;
......@@ -209,7 +155,7 @@ public class JsonWebsocket {
@OnOpen
public void onOpen(final Session session) {
final String clientId = ApiHelper.filterId(DEFAULT_CLIENTID_PREFIX, session.getId());
final String clientId = filterId(DEFAULT_CLIENTID_PREFIX, session.getId());
LOGGER.debug("Websocket: Session \"{}\" opened", clientId);
SESSIONS.put(clientId, session);
......
......@@ -10,6 +10,7 @@
<entry key="useCache">false</entry>
<entry key="useCoverageMask">true</entry>
<entry key="useIsochroneStatistics">true</entry>
<entry key="useJson2DiskSerializeation">false</entry>
<entry key="useMultiGeometries">true</entry>
<!-- When enabled, this shows a small coverage area around each
transportation station reached. Only works with outputType
......
......@@ -3,48 +3,48 @@ package at.uibk.dbis.isomap.web.api;
import org.testng.Assert;
import org.testng.annotations.Test;
public class ApiHelperTest {
public class AbstractJsonApiTest {
private static final String DEFAULT_CLIENTID_PREFIX = "test_";
@Test
public void testEmptyClientId() {
final String result = ApiHelper.filterId(DEFAULT_CLIENTID_PREFIX, null);
final String result = AbstractJsonApi.filterId(DEFAULT_CLIENTID_PREFIX, null);
Assert.assertTrue(result.matches(DEFAULT_CLIENTID_PREFIX + ".*"));
}
@Test
public void testJettyWebsocketId() {
final String result = ApiHelper.filterId(DEFAULT_CLIENTID_PREFIX, "websocket-1");
final String result = AbstractJsonApi.filterId(DEFAULT_CLIENTID_PREFIX, "websocket-1");
Assert.assertEquals(result, "websocket_1");
}
@Test
public void testLowerCaseId() {
final String result = ApiHelper.filterId(DEFAULT_CLIENTID_PREFIX, "MyTEstID");
final String result = AbstractJsonApi.filterId(DEFAULT_CLIENTID_PREFIX, "MyTEstID");
Assert.assertEquals(result, "mytestid");
}
@Test
public void testRemoveSpecialChars() {
final String result = ApiHelper.filterId(DEFAULT_CLIENTID_PREFIX, "mytestid-[]{}()\"'&\\");
final String result = AbstractJsonApi.filterId(DEFAULT_CLIENTID_PREFIX, "mytestid-[]{}()\"'&\\");
Assert.assertEquals(result, "mytestid_");
}
@Test
public void testRemoveSpecialCharsEmpty() {
final String result = ApiHelper.filterId(DEFAULT_CLIENTID_PREFIX, "[]{}()\"'&\\");
final String result = AbstractJsonApi.filterId(DEFAULT_CLIENTID_PREFIX, "[]{}()\"'&\\");
Assert.assertTrue(result.matches(DEFAULT_CLIENTID_PREFIX + ".*"));
}
@Test
public void testRemoveUmlauts() {
final String result = ApiHelper.filterId(DEFAULT_CLIENTID_PREFIX, "myTestId-öäüÖÄÜ");
final String result = AbstractJsonApi.filterId(DEFAULT_CLIENTID_PREFIX, "myTestId-öäüÖÄÜ");
Assert.assertEquals(result, "mytestid_");
}
@Test
public void testRemoveUmlautsEmpty() {
final String result = ApiHelper.filterId(DEFAULT_CLIENTID_PREFIX, "öäüÖÄÜ");
final String result = AbstractJsonApi.filterId(DEFAULT_CLIENTID_PREFIX, "öäüÖÄÜ");
Assert.assertTrue(result.matches(DEFAULT_CLIENTID_PREFIX + ".*"));
}
......
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment