OFBiz
  1. OFBiz
  2. OFBIZ-2208

ServerHit aborts transactions when trying to create entries with duplicate startTime(s).

    Details

    • Type: Bug Bug
    • Status: Reopened
    • Priority: Major Major
    • Resolution: Unresolved
    • Affects Version/s: Release Branch 4.0, SVN trunk
    • Component/s: framework
    • Labels:
      None
    • Environment:

      any

      Description

      org.ofbiz.webapp.stats.ServerHitBin.saveHit(...) causes transactions to be aborted due to duplicate PKs.

      The problem is that said method will try to create two or more entries with identical startTimes (i.e. duplicate hitStartDateTime and the other fields composing the PK: visitId, contentId, hitStartDateTime, hitTypeId) if two or more subsequent requests are made in a sufficiently small interval. This can and will be the case for example if an application rapidly issues requests for similar data. It would usually not be observed when human users cause requests being issued.

      The cause is that the above mentioned method uses

      serverHit.create();

      to store the entries.

      A solution to this is to create or update an existing entry, thus overwriting an existing entry in case there already was an entry, but more importantly avoiding the actual transaction being aborted. This may not satisfy those who want to record each and every server hit even with equal startTimes. For these cases other approaches might be considered ...

      This is an example where a transaction fails due to saveHit(...). In our case an applet tries to pull data off the server and fails ...

      Failure in create operation for entity [ServerHit]: org.ofbiz.entity.GenericEntityException: Error while inserting: [GenericEntity:ServerHit][contentId,gdm.getProductFeatureApplAttrs(java.lang.String)][createdStamp,2009-02-24 10:34:29.454(java.sql.Timestamp)][createdTxStamp,2009-02-24 10:34:29.454(java.sql.Timestamp)][hitStartDateTime,2009-02-24 10:34:29.443(java.sql.Timestamp)][hitTypeId,REQUEST(java.lang.String)][lastUpdatedStamp,2009-02-24 10:34:29.454(java.sql.Timestamp)][lastUpdatedTxStamp,2009-02-24 10:34:29.454(java.sql.Timestamp)][partyId,KR(java.lang.String)][referrerUrl,(java.lang.String)][requestUrl,https://127.0.0.1:8443/gdm/control/getProductFeatureApplAttrs(java.lang.String)][runningTimeMillis,8(java.lang.Long)][serverHostName,Kitty(java.lang.String)][serverIpAddress,192.168.1.70(java.lang.String)][userLoginId,karim(java.lang.String)][visitId,11900(java.lang.String)] (SQL Exception while executing the following:INSERT INTO SERVER_HIT (VISIT_ID, CONTENT_ID, HIT_START_DATE_TIME, HIT_TYPE_ID, NUM_OF_BYTES, RUNNING_TIME_MILLIS, USER_LOGIN_ID, STATUS_ID, REQUEST_URL, REFERRER_URL, SERVER_IP_ADDRESS, SERVER_HOST_NAME, LAST_UPDATED_STAMP, LAST_UPDATED_TX_STAMP, CREATED_STAMP, CREATED_TX_STAMP, INTERNAL_CONTENT_ID, PARTY_ID, ID_BY_IP_CONTACT_MECH_ID, REF_BY_WEB_CONTACT_MECH_ID) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) (Duplicate entry '11900-gdm.getProductFeatureApplAttrs-2009-02-24 10:34:29-REQUEST' for key 'PRIMARY')). Rolling back transaction.
      Exception: org.ofbiz.entity.GenericEntityException

      This issue seems to be related (it refers to the releae branch 4.0 and the same error shows up):

      https://issues.apache.org/jira/browse/OFBIZ-2041?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel

      1. ServerHitBin.java.patch
        2 kB
        Karim Rahimpur
      2. ServerHit.patch
        4 kB
        Karim Rahimpur
      3. ServerHitBin.patch
        0.8 kB
        Adrian Crum
      4. SynchronizedHitBin.patch
        1 kB
        Adrian Crum

        Issue Links

          Activity

          Hide
          Karim Rahimpur added a comment -

          Changes ServerHitBin.saveHit(...) to use create or store instead of create thus giving an alternate approach to the problem mentioned. As said, multiple requests with same PKs would only create one ServerHit entry but this will not make the transaction fail.

          Show
          Karim Rahimpur added a comment - Changes ServerHitBin.saveHit(...) to use create or store instead of create thus giving an alternate approach to the problem mentioned. As said, multiple requests with same PKs would only create one ServerHit entry but this will not make the transaction fail.
          Hide
          Jacques Le Roux added a comment -

          If I remember well this (transactions with the same Timestamp) should not arise if you are using PostGres or Derby but could happen with MySql. This is because Postgres and Derby have milliseconds in Timestamps but not MySql. Moreover, IIRW, OFBiz is enforcing this to be sure to not have duplicates in milliseconds.

          There has been such a question 2 years ago but w/o a clear answer.

          On my side I think your solution is a good one as we don't have to worry too much for ServerHit duplicates. Moreover, this problem should only happen with MySql hence this change should not have any impact for DBMS using milliseconds in Timestamps. So if nobody sees a problem with that I will commit this solution very soon.

          Show
          Jacques Le Roux added a comment - If I remember well this (transactions with the same Timestamp) should not arise if you are using PostGres or Derby but could happen with MySql. This is because Postgres and Derby have milliseconds in Timestamps but not MySql . Moreover, IIRW, OFBiz is enforcing this to be sure to not have duplicates in milliseconds. There has been such a question 2 years ago but w/o a clear answer. On my side I think your solution is a good one as we don't have to worry too much for ServerHit duplicates. Moreover, this problem should only happen with MySql hence this change should not have any impact for DBMS using milliseconds in Timestamps. So if nobody sees a problem with that I will commit this solution very soon.
          Hide
          David E. Jones added a comment -

          Karim: could you verify that you are using MySQL?

          As for a solution, I'd rather see an error in the log than overwrite existing data... which is what the proposal to use createOrStore instead of just create. So no, let's not change it to use createOrStore... better to get the exception and put it in the log.

          Show
          David E. Jones added a comment - Karim: could you verify that you are using MySQL? As for a solution, I'd rather see an error in the log than overwrite existing data... which is what the proposal to use createOrStore instead of just create. So no, let's not change it to use createOrStore... better to get the exception and put it in the log.
          Hide
          Jacques Le Roux added a comment -

          Yes, I agree David, keeping what exists is better.

          Show
          Jacques Le Roux added a comment - Yes, I agree David, keeping what exists is better.
          Hide
          Jacques Le Roux added a comment -

          Also the counter idea is a good one, as Karim proposed I will let the comment in so that people interested will just have to pick the idea.
          Waiting for Karim answer to commit. If you need something like that (counter) Karim you could propose a patch though...

          Show
          Jacques Le Roux added a comment - Also the counter idea is a good one, as Karim proposed I will let the comment in so that people interested will just have to pick the idea. Waiting for Karim answer to commit. If you need something like that (counter) Karim you could propose a patch though...
          Hide
          Jacques Le Roux added a comment -

          The counter idea would have been commited but not this solution has it's incomplete. See revision 750068.

          Show
          Jacques Le Roux added a comment - The counter idea would have been commited but not this solution has it's incomplete. See revision 750068.
          Hide
          Karim Rahimpur added a comment -

          Many thanks for your comments.

          The thing is that it really does not depend on which DBMS you use, MySql's DateTime being coarser than e.g. Derby's Timestamp
          only makes it more probable that a transaction will get aborted due to a 'duplicate' hit when using MySql instead of Derby, but the
          problem will still be there: trying to store ServerHits with the same ServerHit.hitStartDateTime and the other fields of the composite
          PK also being equal.

          I propose a simple solution to this (similar to the counter) and will add a patch accordingly.

          Show
          Karim Rahimpur added a comment - Many thanks for your comments. The thing is that it really does not depend on which DBMS you use, MySql's DateTime being coarser than e.g. Derby's Timestamp only makes it more probable that a transaction will get aborted due to a 'duplicate' hit when using MySql instead of Derby, but the problem will still be there: trying to store ServerHits with the same ServerHit.hitStartDateTime and the other fields of the composite PK also being equal. I propose a simple solution to this (similar to the counter) and will add a patch accordingly.
          Hide
          Karim Rahimpur added a comment -

          This solution is based on the following considerations:

          • there must be a way to distinguish ServerHits independent of the DBMS's granularity for the hitStartDateTime field so that transaction are not aborted by stats operations
          • among possible means of distinguishing is to add a counter or to uniquely identify server hits by other means

          The attached patch approaches the problem by defining the serverHitId field for the ServerHit entity and using it as its PK. When a server hit is saved, a sequenced id is obtained for the hit, thus avoiding any dependency on hitStartDateTime field granularity.

          Show
          Karim Rahimpur added a comment - This solution is based on the following considerations: there must be a way to distinguish ServerHits independent of the DBMS's granularity for the hitStartDateTime field so that transaction are not aborted by stats operations among possible means of distinguishing is to add a counter or to uniquely identify server hits by other means The attached patch approaches the problem by defining the serverHitId field for the ServerHit entity and using it as its PK. When a server hit is saved, a sequenced id is obtained for the hit, thus avoiding any dependency on hitStartDateTime field granularity.
          Hide
          Jacques Le Roux added a comment -

          Thanks Karim,

          This looks like a good solution to me, and I will commit if nobody see a problem with that.

          Show
          Jacques Le Roux added a comment - Thanks Karim, This looks like a good solution to me, and I will commit if nobody see a problem with that.
          Hide
          David E. Jones added a comment -

          This patches substantially changes an entity without providing an upgrade path (ie using the Old* pattern, creating a new entity, data migration service, etc) and so should not be committed as-is.

          Some things that could be done that would not result in a pk change:

          1. soften the error so it is handled locally with just and error message and it doesn't affect anything else in the request
          2. if the create fails add 1 second to the timestamp (could add 1 millisecond for all databases except MySQL) and try again

          Show
          David E. Jones added a comment - This patches substantially changes an entity without providing an upgrade path (ie using the Old* pattern, creating a new entity, data migration service, etc) and so should not be committed as-is. Some things that could be done that would not result in a pk change: 1. soften the error so it is handled locally with just and error message and it doesn't affect anything else in the request 2. if the create fails add 1 second to the timestamp (could add 1 millisecond for all databases except MySQL) and try again
          Hide
          Jacques Le Roux added a comment -

          Ha yes!

          I forgot this point, in case Karim prefers this way : Revisions Requiring Data Migration

          Show
          Jacques Le Roux added a comment - Ha yes! I forgot this point, in case Karim prefers this way : Revisions Requiring Data Migration
          Hide
          Jacques Le Roux added a comment -

          Hi Karim,

          Any update ?

          Show
          Jacques Le Roux added a comment - Hi Karim, Any update ?
          Hide
          Scott Gray added a comment -

          Why close the issue if it represents an unresolved bug?

          Show
          Scott Gray added a comment - Why close the issue if it represents an unresolved bug?
          Hide
          Jacques Le Roux added a comment -

          I thought nobody did care about it since this issue is open for 10 months now...
          Karim seems no longer interested. I had a look and did not find David's directions very obvious because I did not find a related return and I guess we should change something in GenericValue.store, I gave up...
          So as it seems not a problem for nobody, I closed it. But I'm happy to re-open, hopefully I will not have to re-close it in the future...

          Show
          Jacques Le Roux added a comment - I thought nobody did care about it since this issue is open for 10 months now... Karim seems no longer interested. I had a look and did not find David's directions very obvious because I did not find a related return and I guess we should change something in GenericValue.store, I gave up... So as it seems not a problem for nobody, I closed it. But I'm happy to re-open, hopefully I will not have to re-close it in the future...
          Hide
          Adrian Crum added a comment -

          The attached patch implements David's suggestion.

          I don't like that solution either, because in a multi-threaded, multi-cpu environment, duplicates are still possible. It would be better to ignore the supplied long value, and have a synchronized method that gets the current time - that way unique PKs are guaranteed.

          By the way, the error is repeatable in the entity reference screen - which fires two requests simultaneously.

          Show
          Adrian Crum added a comment - The attached patch implements David's suggestion. I don't like that solution either, because in a multi-threaded, multi-cpu environment, duplicates are still possible. It would be better to ignore the supplied long value, and have a synchronized method that gets the current time - that way unique PKs are guaranteed. By the way, the error is repeatable in the entity reference screen - which fires two requests simultaneously.
          Hide
          Adrian Crum added a comment -

          SynchronizedHitBin.patch fixes the problem, but it ignores the long value supplied to it.

          Show
          Adrian Crum added a comment - SynchronizedHitBin.patch fixes the problem, but it ignores the long value supplied to it.
          Hide
          Jacques Le Roux added a comment -

          Hi Adrian,

          Couldn't this synchronization slow down things?

          Show
          Jacques Le Roux added a comment - Hi Adrian, Couldn't this synchronization slow down things?
          Hide
          Jacques Le Roux added a comment -

          Hi Adrian,

          How do you reproduce in the entity reference screen ? I see nothing special in log.

          Show
          Jacques Le Roux added a comment - Hi Adrian, How do you reproduce in the entity reference screen ? I see nothing special in log.
          Hide
          Jacques Le Roux added a comment -

          If anybody see a problem with Adrian's patch I will commit it soon...

          Show
          Jacques Le Roux added a comment - If anybody see a problem with Adrian's patch I will commit it soon...
          Hide
          Jacques Le Roux added a comment -

          Thanks Adrian,

          I have finally commited your patch in trunk at r887916, R9.04 at r887917

          I have added some comments in snv log. Here they are

          Note: If synchronization proves to slow down sites we could introduce a properties in serverstats.properties to switch from using it or not since I did not remove startTime from the method signature
          Then we will use one or the other lines

          • serverHit.set("hitStartDateTime", new java.sql.Timestamp(startTime));
            + serverHit.set("hitStartDateTime", getNowTimestamp());
          Show
          Jacques Le Roux added a comment - Thanks Adrian, I have finally commited your patch in trunk at r887916, R9.04 at r887917 I have added some comments in snv log. Here they are Note: If synchronization proves to slow down sites we could introduce a properties in serverstats.properties to switch from using it or not since I did not remove startTime from the method signature Then we will use one or the other lines serverHit.set("hitStartDateTime", new java.sql.Timestamp(startTime)); + serverHit.set("hitStartDateTime", getNowTimestamp());
          Hide
          Jacques Le Roux added a comment -

          Forgot to reopen this issue: I reverted in trunk at r888111 and in R9.04 at r888113

          Show
          Jacques Le Roux added a comment - Forgot to reopen this issue: I reverted in trunk at r888111 and in R9.04 at r888113
          Hide
          Jacques Le Roux added a comment -

          For the synchronized solution: when you think about it
          new java.sql.Timestamp(System.currentTimeMillis());
          give different values, but MySql is unable to store them as different: http://bugs.mysql.com/bug.php?id=8523.

          Show
          Jacques Le Roux added a comment - For the synchronized solution: when you think about it new java.sql.Timestamp(System.currentTimeMillis()); give different values, but MySql is unable to store them as different: http://bugs.mysql.com/bug.php?id=8523 .
          Hide
          Adam Heath added a comment -

          Any solution to this problem that uses a time value for the solution is broken.

          Show
          Adam Heath added a comment - Any solution to this problem that uses a time value for the solution is broken.
          Hide
          Jacques Le Roux added a comment -

          Hi Adam,

          Have you a suggestion? Maybe we could follow Karim idea but then we would have to create an DB upgrade path. Personnally, as I have currently no needs, I will do it only if a client sponsors it.

          Show
          Jacques Le Roux added a comment - Hi Adam, Have you a suggestion? Maybe we could follow Karim idea but then we would have to create an DB upgrade path. Personnally, as I have currently no needs, I will do it only if a client sponsors it.
          Hide
          Adam Heath added a comment -

          The reason why it can't be time based, is that is how it currently is. And that is what is broken. The only way to fix this is to use some kind of sequence, maybe not SequenceValue.

          Show
          Adam Heath added a comment - The reason why it can't be time based, is that is how it currently is. And that is what is broken. The only way to fix this is to use some kind of sequence, maybe not SequenceValue.

            People

            • Assignee:
              Jacques Le Roux
              Reporter:
              Karim Rahimpur
            • Votes:
              1 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:

                Development