diff --git a/imixs-archive-api/src/main/java/org/imixs/archive/core/api/SnapshotRestService.java b/imixs-archive-api/src/main/java/org/imixs/archive/core/api/SnapshotRestService.java index c6d37d1..de774a1 100644 --- a/imixs-archive-api/src/main/java/org/imixs/archive/core/api/SnapshotRestService.java +++ b/imixs-archive-api/src/main/java/org/imixs/archive/core/api/SnapshotRestService.java @@ -39,23 +39,6 @@ import java.util.logging.Level; import java.util.logging.Logger; -import jakarta.ejb.EJB; -import jakarta.enterprise.context.RequestScoped; -import jakarta.inject.Inject; -import jakarta.inject.Named; -import jakarta.servlet.http.HttpServletRequest; -import jakarta.ws.rs.Consumes; -import jakarta.ws.rs.Encoded; -import jakarta.ws.rs.GET; -import jakarta.ws.rs.POST; -import jakarta.ws.rs.Path; -import jakarta.ws.rs.PathParam; -import jakarta.ws.rs.Produces; -import jakarta.ws.rs.core.Context; -import jakarta.ws.rs.core.MediaType; -import jakarta.ws.rs.core.Response; -import jakarta.ws.rs.core.UriInfo; - import org.eclipse.microprofile.config.inject.ConfigProperty; import org.imixs.archive.core.SnapshotException; import org.imixs.archive.core.SnapshotService; @@ -74,6 +57,23 @@ import org.imixs.workflow.xml.XMLDocument; import org.imixs.workflow.xml.XMLDocumentAdapter; +import jakarta.ejb.EJB; +import jakarta.enterprise.context.RequestScoped; +import jakarta.inject.Inject; +import jakarta.inject.Named; +import jakarta.servlet.http.HttpServletRequest; +import jakarta.ws.rs.Consumes; +import jakarta.ws.rs.Encoded; +import jakarta.ws.rs.GET; +import jakarta.ws.rs.POST; +import jakarta.ws.rs.Path; +import jakarta.ws.rs.PathParam; +import jakarta.ws.rs.Produces; +import jakarta.ws.rs.core.Context; +import jakarta.ws.rs.core.MediaType; +import jakarta.ws.rs.core.Response; +import jakarta.ws.rs.core.UriInfo; + /** * The SnapshotRestService provides a Rest API to access the snapshot data. *

@@ -97,10 +97,10 @@ public class SnapshotRestService implements Serializable { private static final long serialVersionUID = 1L; - + @Inject @ConfigProperty(name = SnapshotService.ARCHIVE_SERVICE_ENDPOINT) - Optional archiveServiceEndpoint; + Optional archiveServiceEndpoint; @jakarta.ws.rs.core.Context private HttpServletRequest servletRequest; @@ -164,7 +164,7 @@ public Response getWorkItemFile(@PathParam("uniqueid") String uniqueid, @PathPar long l = System.currentTimeMillis(); byte[] fileContent; fileContent = archiveClientService.loadFileFromArchive(fileData); - if (fileContent != null && fileContent.length>0) { + if (fileContent != null && fileContent.length > 0) { Response.ResponseBuilder builder = Response.ok(fileContent, fileData.getContentType()); // found -> return directy. if (debug) { @@ -176,7 +176,7 @@ public Response getWorkItemFile(@PathParam("uniqueid") String uniqueid, @PathPar // Critical situation! // The file data is not available in the cassandra storage // We print a error message and try to load the file from the local snapshot - logger.severe("Failed to load '" + file+"' form imixs-archive - fallback to local snapshot..."); + logger.severe("Failed to load '" + file + "' form imixs-archive - fallback to local snapshot..."); } } catch (RestAPIException e) { @@ -220,7 +220,7 @@ public XMLDataCollection getDocumentsBySyncPoint(@PathParam("syncpoint") long lS query += " WHERE document.modified > '" + isoFormat.format(syncpoint) + "'"; query += " AND document.type LIKE '" + SnapshotService.TYPE_PRAFIX + "%' "; query += " ORDER BY document.modified ASC"; - logger.finest("......QUERY=" + query); + logger.info("......QUERY-1=" + query); result = documentService.getDocumentsByQuery(query, 1); // do we found new data? @@ -245,20 +245,20 @@ public XMLDataCollection getDocumentsBySyncPoint(@PathParam("syncpoint") long lS query = "SELECT document FROM Document AS document "; query += " WHERE document.modified = '" + isoFormat.format(syncpoint) + "'"; query += " AND document.type LIKE '" + SnapshotService.TYPE_PRAFIX + "%' "; - logger.finest("......QUERY=" + query); + logger.info("......QUERY-2=" + query); result = documentService.getDocumentsByQuery(query, 16 + 1); - // if more than 16 syncpoints with the same modifed time stamp exists we have in - // deed a problem + // if more than 16 syncPoints with the same modified time stamp exists we have + // in deed a problem if (result.size() > 16) { throw new SnapshotException(SnapshotException.INVALID_DATA, - "more than 16 document entites are found with the same modified timestamp. " - + "We assumed that this case is impossible. Sync is not possible."); + "more than 16 document entities found with the same modified timestamp. " + + "We assumed that this case is impossible. Sync is not possible and will be terminated..."); } if (result.size() == 0) { throw new SnapshotException(SnapshotException.INVALID_DATA, "failed to load snapshot by modified timestamp. " - + "We assumed that this case is impossible. Sync is not possible."); + + "We assumed that this case is impossible. Sync is not possible and will be terminated..."); } return XMLDataCollectionAdapter.getDataCollection(result); @@ -333,8 +333,8 @@ public Response postSnapshot(XMLDocument xmlworkitem) { // Explicit write archive event log entry to update ArchiveService... if (archiveServiceEndpoint.isPresent() && !archiveServiceEndpoint.get().isEmpty()) { eventLogService.createEvent(SnapshotService.EVENTLOG_TOPIC_ADD, snapshotID); - } - + } + logger.info("......document '" + originUnqiueID + "' restored."); return Response.ok(XMLDataCollectionAdapter.getDataCollection(document), MediaType.APPLICATION_XML).build(); diff --git a/imixs-archive-service/src/main/java/org/imixs/archive/service/SyncScheduler.java b/imixs-archive-service/src/main/java/org/imixs/archive/service/SyncScheduler.java index cb06c26..537cd28 100644 --- a/imixs-archive-service/src/main/java/org/imixs/archive/service/SyncScheduler.java +++ b/imixs-archive-service/src/main/java/org/imixs/archive/service/SyncScheduler.java @@ -3,6 +3,13 @@ import java.util.Optional; import java.util.logging.Logger; +import org.eclipse.microprofile.config.inject.ConfigProperty; +import org.imixs.melman.BasicAuthenticator; +import org.imixs.melman.DocumentClient; +import org.imixs.melman.EventLogClient; +import org.imixs.melman.FormAuthenticator; +import org.imixs.melman.RestAPIException; + import jakarta.annotation.PostConstruct; import jakarta.annotation.Resource; import jakarta.annotation.security.DeclareRoles; @@ -17,13 +24,6 @@ import jakarta.ws.rs.NotFoundException; import jakarta.ws.rs.client.ClientRequestFilter; -import org.eclipse.microprofile.config.inject.ConfigProperty; -import org.imixs.melman.BasicAuthenticator; -import org.imixs.melman.DocumentClient; -import org.imixs.melman.EventLogClient; -import org.imixs.melman.FormAuthenticator; -import org.imixs.melman.RestAPIException; - /** * The SyncScheduler starts a TimerService to pull new snapshot events from the * workflow instance and push the snapshot data into the cassandra cluster @@ -35,14 +35,13 @@ @Startup @Singleton @LocalBean -//@ConcurrencyManagement(ConcurrencyManagementType.BEAN) @DeclareRoles({ "org.imixs.ACCESSLEVEL.MANAGERACCESS" }) @RunAs("org.imixs.ACCESSLEVEL.MANAGERACCESS") public class SyncScheduler { // timeout interval in ms @Inject - @ConfigProperty(name = ImixsArchiveApp.WORKFLOW_SYNC_INTERVAL, defaultValue = "1000") + @ConfigProperty(name = ImixsArchiveApp.WORKFLOW_SYNC_INTERVAL, defaultValue = "5000") long interval; @Inject @@ -108,12 +107,14 @@ public void run(Timer timer) { EventLogClient eventLogClient = null; ClientRequestFilter authenticator = null; + logger.fine("--- run timeout.... timerinfo= " + timer.getInfo()); try { // Test the authentication method and create a corresponding Authenticator if ("Form".equalsIgnoreCase(workflowServiceAuthMethod.get())) { // test if a JSESSIONID exists? String jSessionID = (String) timer.getInfo(); if (jSessionID == null || jSessionID.isEmpty()) { + logger.fine("--- jSessionID is empty - need new login...."); // no - we need to login first and store the JSESSIONID in a new timer object... // create a FormAuthenticator FormAuthenticator formAuth = new FormAuthenticator(workflowServiceEndpoint.get(), @@ -121,16 +122,21 @@ public void run(Timer timer) { // Authentication successful - do we have a JSESSIONID? String jsessionID = formAuth.getJsessionID(); if (jsessionID != null && !jsessionID.isEmpty()) { + logger.fine("--- reinitialze timer with new jSessionID : " + jsessionID + " and interval=" + + interval); // yes - terminate existing timer and create a new one with the JSESSIONID + timer.cancel(); final TimerConfig timerConfig = new TimerConfig(); timerConfig.setInfo(jsessionID); timerConfig.setPersistent(false); timerService.createIntervalTimer(interval, interval, timerConfig); - logger.info("successful connected: " + workflowServiceEndpoint.get()); + logger.fine("---created new timer"); + logger.info("successful connected: " + workflowServiceEndpoint.get() + " new Timer created..."); return; } } else { + logger.fine("--- reuse jSessionID " + jSessionID + " for login...."); // we have already a jsessionCooke Data object - so create a new // FormAuthenticator form the JSESSIONID FormAuthenticator formAuth = new FormAuthenticator(workflowServiceEndpoint.get(), jSessionID); @@ -150,11 +156,12 @@ public void run(Timer timer) { documentClient.registerClientRequestFilter(authenticator); eventLogClient = new EventLogClient(workflowServiceEndpoint.get()); eventLogClient.registerClientRequestFilter(authenticator); - + logger.fine("--- process event log...."); // release dead locks... archiveSyncService.releaseDeadLocks(eventLogClient); // process the eventLog... archiveSyncService.processEventLog(eventLogClient, documentClient); + logger.fine("--- process event log completed."); } else { // no valid Authenticator! logger.warning("unable to connect: " + workflowServiceEndpoint); diff --git a/imixs-archive-service/src/main/java/org/imixs/archive/service/SyncService.java b/imixs-archive-service/src/main/java/org/imixs/archive/service/SyncService.java index 972713d..5845047 100644 --- a/imixs-archive-service/src/main/java/org/imixs/archive/service/SyncService.java +++ b/imixs-archive-service/src/main/java/org/imixs/archive/service/SyncService.java @@ -5,13 +5,6 @@ import java.util.logging.Level; import java.util.logging.Logger; -import jakarta.ejb.EJBException; -import jakarta.ejb.LocalBean; -import jakarta.ejb.Stateless; -import jakarta.ejb.TransactionAttribute; -import jakarta.ejb.TransactionAttributeType; -import jakarta.inject.Inject; - import org.eclipse.microprofile.config.inject.ConfigProperty; import org.imixs.archive.service.cassandra.DataService; import org.imixs.melman.DocumentClient; @@ -20,6 +13,13 @@ import org.imixs.workflow.ItemCollection; import org.imixs.workflow.exceptions.InvalidAccessException; +import jakarta.ejb.EJBException; +import jakarta.ejb.LocalBean; +import jakarta.ejb.Stateless; +import jakarta.ejb.TransactionAttribute; +import jakarta.ejb.TransactionAttributeType; +import jakarta.inject.Inject; + /** * The SyncService pulls a Snapshot into an Apache Cassandra archive. The * service uses an asynchronous mechanism based on the Imixs EventLog. @@ -81,6 +81,8 @@ public void processEventLog(EventLogClient eventLogClient, DocumentClient docume String id = null; String ref = null; ItemCollection snapshot = null; + long count = 0; + long duration = System.currentTimeMillis(); if (documentClient == null || eventLogClient == null) { // no client object @@ -121,6 +123,7 @@ public void processEventLog(EventLogClient eventLogClient, DocumentClient docume eventLogClient.createEventLogEntry(ImixsArchiveApp.EVENTLOG_TOPIC_BACKUP, ref, null); } } + count++; } catch (InvalidAccessException | EJBException | ArchiveException e) { // we also catch EJBExceptions here because we do not want to cancel the // ManagedScheduledExecutorService @@ -131,6 +134,7 @@ public void processEventLog(EventLogClient eventLogClient, DocumentClient docume // eventLogService.removeEvent(eventLogEntry.getId()); } } + logger.info("Processed " + count + " snapshot events in " + (System.currentTimeMillis() - duration) + "ms"); } diff --git a/imixs-archive-service/src/main/java/org/imixs/archive/service/resync/ResyncService.java b/imixs-archive-service/src/main/java/org/imixs/archive/service/resync/ResyncService.java index a24ff56..29ee000 100644 --- a/imixs-archive-service/src/main/java/org/imixs/archive/service/resync/ResyncService.java +++ b/imixs-archive-service/src/main/java/org/imixs/archive/service/resync/ResyncService.java @@ -223,7 +223,7 @@ void onTimeout(jakarta.ejb.Timer timer) throws Exception { totalSize = metaData.getItemValueLong(ITEM_SYNCSIZE); // ...start sync - logger.info("...start syncronizing at syncpoint " + new Date(syncPoint) + "..."); + logger.info("...start synchronizing at syncPoint " + new Date(syncPoint) + "..."); // Daylight Saving Time Correction // issue #53 @@ -235,14 +235,16 @@ void onTimeout(jakarta.ejb.Timer timer) throws Exception { } while (true) { - + long lReadTime = System.currentTimeMillis(); + long lTotalTime = System.currentTimeMillis(); XMLDataCollection xmlDataCollection = remoteAPIService.readSyncData(syncPoint); - if (xmlDataCollection != null) { + logger.info("...found " + xmlDataCollection.getDocument().length + " snapshots at syncpoint " + + new Date(syncPoint) + " in " + (System.currentTimeMillis() - lReadTime) + "ms"); List snapshotList = Arrays.asList(xmlDataCollection.getDocument()); for (XMLDocument xmlDocument : snapshotList) { - + long lSyncTime = System.currentTimeMillis(); ItemCollection snapshot = XMLDocumentAdapter.putDocument(xmlDocument); // update snypoint @@ -265,12 +267,17 @@ void onTimeout(jakarta.ejb.Timer timer) throws Exception { + e.getMessage()); // we continue.... } + logger.info( + "...snapshot '" + snapshot.getUniqueID() + "' written in " + + (System.currentTimeMillis() - lSyncTime) + "ms"); } else { // This is because in case of a restore, the same snapshot takes a new $modified // item. And we do not want to re-import the snapshot in the next sync cycle. // see issue #40 - logger.fine("...snapshot '" + snapshot.getUniqueID() + "' already exits...."); + logger.info( + "...snapshot '" + snapshot.getUniqueID() + "' already exits - verification took " + + (System.currentTimeMillis() - lSyncTime) + "ms"); } syncread++; @@ -283,6 +290,10 @@ void onTimeout(jakarta.ejb.Timer timer) throws Exception { lastUniqueID = "0"; dataService.saveMetadata(metaData); + logger.info( + "...snapshot '" + snapshot.getUniqueID() + "' synchronized in " + + (System.currentTimeMillis() - lTotalTime) + "ms"); + if (syncStatusHandler.getStatus() == ResyncStatusHandler.STAUS_CANCELED) { break; }