SuccessConsole Output

Skipping 4,576 KB.. Full Log
_23_,
        oasistesta0_.mbv_coverage_count as mbv_cove8_23_,
        oasistesta0_.normative_source_id as normati16_23_,
        oasistesta0_.other_tag_on_assertion as other_ta9_23_,
        oasistesta0_.page_number as page_nu10_23_,
        oasistesta0_.predicate_id as predica17_23_,
        oasistesta0_.prerequisite_id as prerequ18_23_,
        oasistesta0_.prescription_id as prescri19_23_,
        oasistesta0_.status as status11_23_,
        oasistesta0_.target_id as target_20_23_,
        oasistesta0_.testable as testabl12_23_,
        oasistesta0_.tests_coverage_count as tests_c13_23_,
        oasistesta0_.tf_rules_coverage_count as tf_rule14_23_ 
    from
        am_oasis_test_assertion oasistesta0_
12:54:05,494 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,494 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,494 DEBUG [main] Loader:948 - Result set row: 0
12:54:05,494 DEBUG [main] Loader:1480 - Result row: EntityKey[net.ihe.gazelle.oasis.testassertion.OasisTestAssertion#22]
12:54:05,495 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,495 DEBUG [main] StandardQueryCache:104 - Caching query results in region: org.hibernate.cache.internal.StandardQueryCache; timestamp=6373798893547520
12:54:05,495 DEBUG [main] EhcacheGeneralDataRegion:100 - key: sql: select distinct oasistesta0_.id as id1_23_, oasistesta0_.last_changed as last_cha2_23_, oasistesta0_.last_modifier_id as last_mod3_23_, oasistesta0_.applies_to_count as applies_4_23_, oasistesta0_.assertion_id as assertio5_23_, oasistesta0_.comment as comment6_23_, oasistesta0_.coverage_count as coverage7_23_, oasistesta0_.description_id as descrip15_23_, oasistesta0_.mbv_coverage_count as mbv_cove8_23_, oasistesta0_.normative_source_id as normati16_23_, oasistesta0_.other_tag_on_assertion as other_ta9_23_, oasistesta0_.page_number as page_nu10_23_, oasistesta0_.predicate_id as predica17_23_, oasistesta0_.prerequisite_id as prerequ18_23_, oasistesta0_.prescription_id as prescri19_23_, oasistesta0_.status as status11_23_, oasistesta0_.target_id as target_20_23_, oasistesta0_.testable as testabl12_23_, oasistesta0_.tests_coverage_count as tests_c13_23_, oasistesta0_.tf_rules_coverage_count as tf_rule14_23_ from am_oasis_test_assertion oasistesta0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2 value: [6373798893547520, 22]
12:54:05,495 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,496 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,496 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,496 DEBUG [main] AbstractTransactionImpl:158 - begin
12:54:05,496 DEBUG [org%002ehibernate%002ecache%002einternal%002e%0053tandard%0051uery%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,496 DEBUG [org%002ehibernate%002ecache%002einternal%002e%0053tandard%0051uery%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,496 DEBUG [main] JdbcTransaction:69 - initial autocommit status: true
12:54:05,496 DEBUG [main] JdbcTransaction:71 - disabling autocommit
12:54:05,497 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,497 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,497 DEBUG [main] Collections:76 - Collection dereferenced: [net.ihe.gazelle.oasis.testassertion.OasisTestAssertion.tags#22]
12:54:05,497 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 0 insertions, 0 updates, 2 deletions to 5 objects
12:54:05,497 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 0 (re)creations, 0 updates, 1 removals to 1 collections
12:54:05,497 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,498 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisPredicate{language=0, id=22, content=predicate content}
12:54:05,498 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTarget{idScheme=testing 22, lastChanged=2019-04-24 12:54:05.417407378, testAssertions=null, lastModifierId=null, language=null, id=22, type=null, content=null}
12:54:05,498 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisNormativeSource{derivedSourceItems=null, interpretation=null, textSourceItems=null, lastChanged=2019-04-24 12:54:05.426471284, refSourceItems=null, testAssertions=null, lastModifierId=null, comment=null, id=22, content=null}
12:54:05,498 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTestAssertion{mbv=null, normativeSource=net.ihe.gazelle.oasis.testassertion.OasisNormativeSource#22, pageNumber=null, coverageCount=null, testable=true, description=null, otherTagOnAssertion=null, testSteps=null, predicate=net.ihe.gazelle.oasis.testassertion.OasisPredicate#22, assertionId=Assertion-id22, tfRulesCoverageCount=null, appliesToCount=null, lastModifierId=null, id=22, tfTransactions=null, tfIntegrationProfiles=null, variables=null, lastChanged=2019-04-24 12:54:05.433932768, prerequisite=null, tfActors=null, tfAIPOs=null, tags=[], target=net.ihe.gazelle.oasis.testassertion.OasisTarget#22, mbvCoverageCount=null, tests=null, tfAuditMessages=null, prescription=null, testsCoverageCount=null, tfStandards=null, comment=null, scopes=null, tfRules=null, status=null}
12:54:05,498 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,498 DEBUG [main] UpdateTimestampsCache:88 - Pre-invalidating space [am_oasis_test_assertion_tag], timestamp: 6373799139319808
12:54:05,498 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_test_assertion_tag value: 6373799139319808
12:54:05,499 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,499 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,499 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,499 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,499 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,499 DEBUG [main] SQL:104 - 
    delete 
    from
        am_oasis_test_assertion 
    where
        id=?
12:54:05,499 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,500 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,500 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,500 DEBUG [main] UpdateTimestampsCache:88 - Pre-invalidating space [am_oasis_test_assertion], timestamp: 6373799139328000
12:54:05,501 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_test_assertion value: 6373799139328000
12:54:05,501 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,501 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,501 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,501 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,501 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,501 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,502 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,502 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,502 DEBUG [main] SQL:104 - 
    delete 
    from
        am_oasis_predicate 
    where
        id=?
12:54:05,502 DEBUG [instances.data] Segment:779 - fault removed 0 from heap
12:54:05,502 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,502 DEBUG [instances.data] Segment:796 - fault added 0 on disk
12:54:05,502 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,503 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,503 DEBUG [main] UpdateTimestampsCache:88 - Pre-invalidating space [am_oasis_predicate], timestamp: 6373799139340288
12:54:05,503 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_predicate value: 6373799139340288
12:54:05,503 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,503 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,503 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,504 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,504 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,504 DEBUG [main] AbstractTransactionImpl:173 - committing
12:54:05,504 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,504 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,504 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 0 insertions, 0 updates, 0 deletions to 3 objects
12:54:05,504 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
12:54:05,504 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,505 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTarget{idScheme=testing 22, lastChanged=2019-04-24 12:54:05.417407378, testAssertions=null, lastModifierId=null, language=null, id=22, type=null, content=null}
12:54:05,505 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisNormativeSource{derivedSourceItems=null, interpretation=null, textSourceItems=null, lastChanged=2019-04-24 12:54:05.426471284, refSourceItems=null, testAssertions=null, lastModifierId=null, comment=null, id=22, content=null}
12:54:05,505 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,505 DEBUG [main] JdbcTransaction:113 - committed JDBC Connection
12:54:05,505 DEBUG [main] JdbcTransaction:126 - re-enabling autocommit
12:54:05,505 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,506 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,506 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,506 DEBUG [main] UpdateTimestampsCache:125 - Invalidating space [am_oasis_predicate], timestamp: 6373798893592576
12:54:05,506 DEBUG [instances.data] Segment:779 - fault removed 0 from heap
12:54:05,506 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_predicate value: 6373798893592576
12:54:05,506 DEBUG [instances.data] Segment:796 - fault added 0 on disk
12:54:05,506 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,507 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,507 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,507 DEBUG [main] UpdateTimestampsCache:125 - Invalidating space [am_oasis_test_assertion], timestamp: 6373798893592576
12:54:05,507 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,507 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_test_assertion value: 6373798893592576
12:54:05,507 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,507 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,507 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,507 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,507 DEBUG [main] UpdateTimestampsCache:125 - Invalidating space [am_oasis_test_assertion_tag], timestamp: 6373798893592576
12:54:05,507 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,507 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_test_assertion_tag value: 6373798893592576
12:54:05,508 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,508 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,508 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,508 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,508 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,508 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,508 DEBUG [main] StandardQueryCache:138 - Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache
12:54:05,508 DEBUG [main] EhcacheGeneralDataRegion:69 - key: sql: select distinct oasispredi0_.id as id1_17_, oasispredi0_.content as content2_17_, oasispredi0_.language as language3_17_ from am_oasis_predicate oasispredi0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2
12:54:05,509 DEBUG [main] StandardQueryCache:212 - Checking query spaces are up-to-date: [am_oasis_predicate]
12:54:05,509 DEBUG [main] EhcacheGeneralDataRegion:69 - key: am_oasis_predicate
12:54:05,509 DEBUG [main] UpdateTimestampsCache:175 - [am_oasis_predicate] last update timestamp: 6373798893592576, result set timestamp: 6373798893080576
12:54:05,509 DEBUG [main] StandardQueryCache:151 - Cached query results were not up-to-date
12:54:05,509 DEBUG [main] SQL:104 - 
    select
        distinct oasispredi0_.id as id1_17_,
        oasispredi0_.content as content2_17_,
        oasispredi0_.language as language3_17_ 
    from
        am_oasis_predicate oasispredi0_
12:54:05,509 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,509 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,510 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,510 DEBUG [main] StandardQueryCache:104 - Caching query results in region: org.hibernate.cache.internal.StandardQueryCache; timestamp=6373798893608960
12:54:05,510 DEBUG [main] EhcacheGeneralDataRegion:100 - key: sql: select distinct oasispredi0_.id as id1_17_, oasispredi0_.content as content2_17_, oasispredi0_.language as language3_17_ from am_oasis_predicate oasispredi0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2 value: [6373798893608960]
12:54:05,510 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,510 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,510 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,511 DEBUG [org%002ehibernate%002ecache%002einternal%002e%0053tandard%0051uery%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,511 DEBUG [org%002ehibernate%002ecache%002einternal%002e%0053tandard%0051uery%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,511 DEBUG [main] StandardQueryCache:138 - Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache
12:54:05,511 DEBUG [main] EhcacheGeneralDataRegion:69 - key: sql: select distinct oasistarge0_.id as id1_22_, oasistarge0_.last_changed as last_cha2_22_, oasistarge0_.last_modifier_id as last_mod3_22_, oasistarge0_.content as content4_22_, oasistarge0_.idScheme as idScheme5_22_, oasistarge0_.language as language6_22_, oasistarge0_.type as type7_22_ from am_oasis_target oasistarge0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2
12:54:05,511 DEBUG [main] StandardQueryCache:212 - Checking query spaces are up-to-date: [am_oasis_target]
12:54:05,511 DEBUG [main] EhcacheGeneralDataRegion:69 - key: am_oasis_target
12:54:05,511 DEBUG [main] UpdateTimestampsCache:175 - [am_oasis_target] last update timestamp: 6373798893260801, result set timestamp: 6373798893096960
12:54:05,511 DEBUG [main] StandardQueryCache:151 - Cached query results were not up-to-date
12:54:05,511 DEBUG [main] SQL:104 - 
    select
        distinct oasistarge0_.id as id1_22_,
        oasistarge0_.last_changed as last_cha2_22_,
        oasistarge0_.last_modifier_id as last_mod3_22_,
        oasistarge0_.content as content4_22_,
        oasistarge0_.idScheme as idScheme5_22_,
        oasistarge0_.language as language6_22_,
        oasistarge0_.type as type7_22_ 
    from
        am_oasis_target oasistarge0_
12:54:05,512 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,512 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,512 DEBUG [main] Loader:948 - Result set row: 0
12:54:05,512 DEBUG [main] Loader:1480 - Result row: EntityKey[net.ihe.gazelle.oasis.testassertion.OasisTarget#22]
12:54:05,512 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,512 DEBUG [main] StandardQueryCache:104 - Caching query results in region: org.hibernate.cache.internal.StandardQueryCache; timestamp=6373798893617152
12:54:05,513 DEBUG [main] EhcacheGeneralDataRegion:100 - key: sql: select distinct oasistarge0_.id as id1_22_, oasistarge0_.last_changed as last_cha2_22_, oasistarge0_.last_modifier_id as last_mod3_22_, oasistarge0_.content as content4_22_, oasistarge0_.idScheme as idScheme5_22_, oasistarge0_.language as language6_22_, oasistarge0_.type as type7_22_ from am_oasis_target oasistarge0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2 value: [6373798893617152, 22]
12:54:05,513 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,513 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,513 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,513 DEBUG [main] AbstractTransactionImpl:158 - begin
12:54:05,513 DEBUG [org%002ehibernate%002ecache%002einternal%002e%0053tandard%0051uery%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,513 DEBUG [main] JdbcTransaction:69 - initial autocommit status: true
12:54:05,513 DEBUG [main] JdbcTransaction:71 - disabling autocommit
12:54:05,513 DEBUG [org%002ehibernate%002ecache%002einternal%002e%0053tandard%0051uery%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,514 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,514 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,514 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 0 insertions, 0 updates, 1 deletions to 3 objects
12:54:05,514 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
12:54:05,514 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,514 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTarget{idScheme=testing 22, lastChanged=2019-04-24 12:54:05.417407378, testAssertions=null, lastModifierId=null, language=null, id=22, type=null, content=null}
12:54:05,514 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisNormativeSource{derivedSourceItems=null, interpretation=null, textSourceItems=null, lastChanged=2019-04-24 12:54:05.426471284, refSourceItems=null, testAssertions=null, lastModifierId=null, comment=null, id=22, content=null}
12:54:05,514 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,514 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,515 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,515 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,515 DEBUG [main] SQL:104 - 
    delete 
    from
        am_oasis_target 
    where
        id=?
12:54:05,515 DEBUG [instances.data] Segment:779 - fault removed 0 from heap
12:54:05,515 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,515 DEBUG [instances.data] Segment:796 - fault added 0 on disk
12:54:05,515 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,516 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,516 DEBUG [main] UpdateTimestampsCache:88 - Pre-invalidating space [am_oasis_target], timestamp: 6373799139393536
12:54:05,516 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_target value: 6373799139393536
12:54:05,516 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,516 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,516 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,517 DEBUG [main] AbstractTransactionImpl:173 - committing
12:54:05,517 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,517 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,517 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,517 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,517 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 0 insertions, 0 updates, 0 deletions to 2 objects
12:54:05,517 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
12:54:05,517 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,517 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisNormativeSource{derivedSourceItems=null, interpretation=null, textSourceItems=null, lastChanged=2019-04-24 12:54:05.426471284, refSourceItems=null, testAssertions=null, lastModifierId=null, comment=null, id=22, content=null}
12:54:05,517 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,518 DEBUG [main] JdbcTransaction:113 - committed JDBC Connection
12:54:05,518 DEBUG [main] JdbcTransaction:126 - re-enabling autocommit
12:54:05,518 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,518 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,518 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,519 DEBUG [main] UpdateTimestampsCache:125 - Invalidating space [am_oasis_target], timestamp: 6373798893645824
12:54:05,519 DEBUG [instances.data] Segment:779 - fault removed 0 from heap
12:54:05,519 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_target value: 6373798893645824
12:54:05,519 DEBUG [instances.data] Segment:796 - fault added 0 on disk
12:54:05,519 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,519 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,519 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,519 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,519 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,519 DEBUG [main] StandardQueryCache:138 - Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache
12:54:05,520 DEBUG [main] EhcacheGeneralDataRegion:69 - key: sql: select distinct oasisnorma0_.id as id1_13_, oasisnorma0_.last_changed as last_cha2_13_, oasisnorma0_.last_modifier_id as last_mod3_13_, oasisnorma0_.comment_id as comment_5_13_, oasisnorma0_.content as content4_13_, oasisnorma0_.interpretation_id as interpre6_13_ from am_oasis_normative_source oasisnorma0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2
12:54:05,520 DEBUG [main] StandardQueryCache:212 - Checking query spaces are up-to-date: [am_oasis_normative_source]
12:54:05,520 DEBUG [main] EhcacheGeneralDataRegion:69 - key: am_oasis_normative_source
12:54:05,520 DEBUG [main] UpdateTimestampsCache:175 - [am_oasis_normative_source] last update timestamp: 6373798893293568, result set timestamp: 6373798893142016
12:54:05,520 DEBUG [main] StandardQueryCache:151 - Cached query results were not up-to-date
12:54:05,520 DEBUG [main] SQL:104 - 
    select
        distinct oasisnorma0_.id as id1_13_,
        oasisnorma0_.last_changed as last_cha2_13_,
        oasisnorma0_.last_modifier_id as last_mod3_13_,
        oasisnorma0_.comment_id as comment_5_13_,
        oasisnorma0_.content as content4_13_,
        oasisnorma0_.interpretation_id as interpre6_13_ 
    from
        am_oasis_normative_source oasisnorma0_
12:54:05,520 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,520 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,521 DEBUG [main] Loader:948 - Result set row: 0
12:54:05,521 DEBUG [main] Loader:1480 - Result row: EntityKey[net.ihe.gazelle.oasis.testassertion.OasisNormativeSource#22]
12:54:05,521 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,521 DEBUG [main] StandardQueryCache:104 - Caching query results in region: org.hibernate.cache.internal.StandardQueryCache; timestamp=6373798893654016
12:54:05,521 DEBUG [main] EhcacheGeneralDataRegion:100 - key: sql: select distinct oasisnorma0_.id as id1_13_, oasisnorma0_.last_changed as last_cha2_13_, oasisnorma0_.last_modifier_id as last_mod3_13_, oasisnorma0_.comment_id as comment_5_13_, oasisnorma0_.content as content4_13_, oasisnorma0_.interpretation_id as interpre6_13_ from am_oasis_normative_source oasisnorma0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2 value: [6373798893654016, 22]
12:54:05,521 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,522 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,522 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,522 DEBUG [main] AbstractTransactionImpl:158 - begin
12:54:05,522 DEBUG [org%002ehibernate%002ecache%002einternal%002e%0053tandard%0051uery%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,522 DEBUG [main] JdbcTransaction:69 - initial autocommit status: true
12:54:05,522 DEBUG [main] JdbcTransaction:71 - disabling autocommit
12:54:05,522 DEBUG [org%002ehibernate%002ecache%002einternal%002e%0053tandard%0051uery%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,522 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,522 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,522 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 0 insertions, 0 updates, 1 deletions to 2 objects
12:54:05,523 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
12:54:05,523 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,523 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisNormativeSource{derivedSourceItems=null, interpretation=null, textSourceItems=null, lastChanged=2019-04-24 12:54:05.426471284, refSourceItems=null, testAssertions=null, lastModifierId=null, comment=null, id=22, content=null}
12:54:05,523 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,523 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,523 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,523 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,524 DEBUG [main] SQL:104 - 
    delete 
    from
        am_oasis_normative_source 
    where
        id=?
12:54:05,524 DEBUG [instances.data] Segment:779 - fault removed 0 from heap
12:54:05,524 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,524 DEBUG [instances.data] Segment:796 - fault added 0 on disk
12:54:05,524 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,525 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,525 DEBUG [main] UpdateTimestampsCache:88 - Pre-invalidating space [am_oasis_normative_source], timestamp: 6373799139430400
12:54:05,525 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_normative_source value: 6373799139430400
12:54:05,525 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,525 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,525 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,525 DEBUG [main] AbstractTransactionImpl:173 - committing
12:54:05,526 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,526 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,526 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,526 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,526 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
12:54:05,526 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
12:54:05,526 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,526 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,527 DEBUG [main] JdbcTransaction:113 - committed JDBC Connection
12:54:05,527 DEBUG [main] JdbcTransaction:126 - re-enabling autocommit
12:54:05,527 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,527 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,527 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,527 DEBUG [main] UpdateTimestampsCache:125 - Invalidating space [am_oasis_normative_source], timestamp: 6373798893678593
12:54:05,527 DEBUG [instances.data] Segment:779 - fault removed 0 from heap
12:54:05,527 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_normative_source value: 6373798893678593
12:54:05,528 DEBUG [instances.data] Segment:796 - fault added 0 on disk
12:54:05,528 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,528 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,528 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,528 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,528 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,528 DEBUG [main] StandardQueryCache:138 - Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache
12:54:05,529 DEBUG [main] EhcacheGeneralDataRegion:69 - key: sql: select distinct oasisdescr0_.id as id1_11_, oasisdescr0_.last_changed as last_cha2_11_, oasisdescr0_.last_modifier_id as last_mod3_11_, oasisdescr0_.content as content4_11_ from am_oasis_description oasisdescr0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2
12:54:05,529 DEBUG [main] StandardQueryCache:212 - Checking query spaces are up-to-date: [am_oasis_description]
12:54:05,529 DEBUG [main] EhcacheGeneralDataRegion:69 - key: am_oasis_description
12:54:05,529 DEBUG [main] EhcacheGeneralDataRegion:76 - Element for key am_oasis_description is null
12:54:05,529 DEBUG [main] StandardQueryCache:156 - Returning cached query results
12:54:05,530 DEBUG [main] StandardQueryCache:138 - Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache
12:54:05,530 DEBUG [main] EhcacheGeneralDataRegion:69 - key: sql: select distinct oasistag0_.id as id1_21_, oasistag0_.content as content2_21_, oasistag0_.name as name3_21_ from am_oasis_tag oasistag0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2
12:54:05,530 DEBUG [main] StandardQueryCache:212 - Checking query spaces are up-to-date: [am_oasis_tag]
12:54:05,530 DEBUG [main] EhcacheGeneralDataRegion:69 - key: am_oasis_tag
12:54:05,530 DEBUG [main] EhcacheGeneralDataRegion:76 - Element for key am_oasis_tag is null
12:54:05,530 DEBUG [main] StandardQueryCache:156 - Returning cached query results
12:54:05,530 DEBUG [main] StandardQueryCache:138 - Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache
12:54:05,531 DEBUG [main] EhcacheGeneralDataRegion:69 - key: sql: select distinct oasisvaria0_.id as id1_27_, oasisvaria0_.last_changed as last_cha2_27_, oasisvaria0_.last_modifier_id as last_mod3_27_, oasisvaria0_.content as content4_27_, oasisvaria0_.language as language5_27_, oasisvaria0_.name as name6_27_ from am_oasis_variable oasisvaria0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2
12:54:05,531 DEBUG [main] StandardQueryCache:212 - Checking query spaces are up-to-date: [am_oasis_variable]
12:54:05,531 DEBUG [main] EhcacheGeneralDataRegion:69 - key: am_oasis_variable
12:54:05,531 DEBUG [main] EhcacheGeneralDataRegion:76 - Element for key am_oasis_variable is null
12:54:05,531 DEBUG [main] StandardQueryCache:156 - Returning cached query results
12:54:05,531 DEBUG [main] StandardQueryCache:138 - Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache
12:54:05,531 DEBUG [main] EhcacheGeneralDataRegion:69 - key: sql: select distinct oasisprere0_.id as id1_18_, oasisprere0_.last_changed as last_cha2_18_, oasisprere0_.last_modifier_id as last_mod3_18_, oasisprere0_.content as content4_18_, oasisprere0_.language as language5_18_ from am_oasis_prerequisite oasisprere0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2
12:54:05,531 DEBUG [main] StandardQueryCache:212 - Checking query spaces are up-to-date: [am_oasis_prerequisite]
12:54:05,531 DEBUG [main] EhcacheGeneralDataRegion:69 - key: am_oasis_prerequisite
12:54:05,532 DEBUG [main] EhcacheGeneralDataRegion:76 - Element for key am_oasis_prerequisite is null
12:54:05,532 DEBUG [main] StandardQueryCache:156 - Returning cached query results
12:54:05,532 DEBUG [main] StandardQueryCache:138 - Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache
12:54:05,532 DEBUG [main] EhcacheGeneralDataRegion:69 - key: sql: select distinct oasisrefso0_.id as id1_20_, oasisrefso0_.last_changed as last_cha2_20_, oasisrefso0_.last_modifier_id as last_mod3_20_, oasisrefso0_.document_id as document4_20_, oasisrefso0_.name as name5_20_, oasisrefso0_.resource_provenance_id as resource6_20_, oasisrefso0_.revision_id as revision7_20_, oasisrefso0_.uri as uri8_20_, oasisrefso0_.version_id as version_9_20_ from am_oasis_ref_source_item oasisrefso0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2
12:54:05,532 DEBUG [main] StandardQueryCache:212 - Checking query spaces are up-to-date: [am_oasis_ref_source_item]
12:54:05,532 DEBUG [main] EhcacheGeneralDataRegion:69 - key: am_oasis_ref_source_item
12:54:05,532 DEBUG [main] EhcacheGeneralDataRegion:76 - Element for key am_oasis_ref_source_item is null
12:54:05,532 DEBUG [main] StandardQueryCache:156 - Returning cached query results
12:54:05,533 DEBUG [main] AbstractTestQueryJunit4:78 - Shuting down Hibernate JPA layer.
12:54:05,533 DEBUG [main] AbstractTestQueryJunit4:66 - setup Hibernate JPA layer.
12:54:05,535 DEBUG [main] AbstractTransactionImpl:158 - begin
12:54:05,535 DEBUG [main] JdbcTransaction:69 - initial autocommit status: true
12:54:05,535 DEBUG [main] JdbcTransaction:71 - disabling autocommit
12:54:05,535 DEBUG [main] SQL:104 - 
    select
        nextval ('am_oasis_predicate_id_seq')
12:54:05,536 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,536 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,536 DEBUG [main] SequenceGenerator:127 - Sequence identifier generated: BasicHolder[java.lang.Integer[23]]
12:54:05,536 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,537 DEBUG [main] AbstractSaveEventListener:130 - Generated identifier: 23, using strategy: org.hibernate.id.SequenceHiLoGenerator
12:54:05,537 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,537 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,537 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 1 insertions, 0 updates, 0 deletions to 2 objects
12:54:05,538 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
12:54:05,538 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,538 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisPredicate{language=0, id=23, content=predicate content}
12:54:05,538 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,538 DEBUG [main] SQL:104 - 
    insert 
    into
        am_oasis_predicate
        (content, language, id) 
    values
        (?, ?, ?)
12:54:05,539 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,539 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,539 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,540 DEBUG [main] UpdateTimestampsCache:88 - Pre-invalidating space [am_oasis_predicate], timestamp: 6373799139491840
12:54:05,540 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_predicate value: 6373799139491840
12:54:05,540 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,540 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,540 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,540 DEBUG [main] AbstractTransactionImpl:173 - committing
12:54:05,540 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,541 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,541 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,541 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,541 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 0 insertions, 0 updates, 0 deletions to 2 objects
12:54:05,541 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
12:54:05,541 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,541 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisPredicate{language=0, id=23, content=predicate content}
12:54:05,542 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,544 DEBUG [main] JdbcTransaction:113 - committed JDBC Connection
12:54:05,544 DEBUG [main] JdbcTransaction:126 - re-enabling autocommit
12:54:05,545 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,545 DEBUG [main] UpdateTimestampsCache:125 - Invalidating space [am_oasis_predicate], timestamp: 6373798893752321
12:54:05,545 DEBUG [instances.data] Segment:779 - fault removed 0 from heap
12:54:05,545 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_predicate value: 6373798893752321
12:54:05,545 DEBUG [instances.data] Segment:796 - fault added 0 on disk
12:54:05,545 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,546 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,546 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,546 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,546 DEBUG [main] AbstractTransactionImpl:158 - begin
12:54:05,546 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,546 DEBUG [main] JdbcTransaction:69 - initial autocommit status: true
12:54:05,546 DEBUG [main] JdbcTransaction:71 - disabling autocommit
12:54:05,546 DEBUG [main] SQL:104 - 
    select
        nextval ('am_oasis_target_id_seq')
12:54:05,547 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,547 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,547 DEBUG [main] SequenceGenerator:127 - Sequence identifier generated: BasicHolder[java.lang.Integer[23]]
12:54:05,547 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,547 DEBUG [main] AbstractSaveEventListener:130 - Generated identifier: 23, using strategy: org.hibernate.id.SequenceHiLoGenerator
12:54:05,548 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,548 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,548 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 1 insertions, 0 updates, 0 deletions to 3 objects
12:54:05,548 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
12:54:05,548 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,548 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisPredicate{language=0, id=23, content=predicate content}
12:54:05,548 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTarget{idScheme=testing 23, lastChanged=2019-04-24 12:54:05.546190049, testAssertions=null, lastModifierId=null, language=null, id=23, type=null, content=null}
12:54:05,548 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,549 DEBUG [main] SQL:104 - 
    insert 
    into
        am_oasis_target
        (last_changed, last_modifier_id, content, idScheme, language, type, id) 
    values
        (?, ?, ?, ?, ?, ?, ?)
12:54:05,549 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,549 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,550 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,550 DEBUG [main] UpdateTimestampsCache:88 - Pre-invalidating space [am_oasis_target], timestamp: 6373799139532800
12:54:05,550 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_target value: 6373799139532800
12:54:05,550 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,551 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,551 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,551 DEBUG [main] AbstractTransactionImpl:173 - committing
12:54:05,551 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,551 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,551 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,551 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,551 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 0 insertions, 0 updates, 0 deletions to 3 objects
12:54:05,551 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
12:54:05,552 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,552 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisPredicate{language=0, id=23, content=predicate content}
12:54:05,552 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTarget{idScheme=testing 23, lastChanged=2019-04-24 12:54:05.546190049, testAssertions=null, lastModifierId=null, language=null, id=23, type=null, content=null}
12:54:05,552 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,552 DEBUG [main] JdbcTransaction:113 - committed JDBC Connection
12:54:05,552 DEBUG [main] JdbcTransaction:126 - re-enabling autocommit
12:54:05,553 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,553 DEBUG [main] UpdateTimestampsCache:125 - Invalidating space [am_oasis_target], timestamp: 6373798893785089
12:54:05,553 DEBUG [instances.data] Segment:779 - fault removed 0 from heap
12:54:05,553 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_target value: 6373798893785089
12:54:05,553 DEBUG [instances.data] Segment:796 - fault added 0 on disk
12:54:05,553 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,554 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,554 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,554 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,554 DEBUG [main] AbstractTransactionImpl:158 - begin
12:54:05,554 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,554 DEBUG [main] JdbcTransaction:69 - initial autocommit status: true
12:54:05,554 DEBUG [main] JdbcTransaction:71 - disabling autocommit
12:54:05,554 DEBUG [main] SQL:104 - 
    select
        nextval ('am_oasis_normative_source_id_seq')
12:54:05,555 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,555 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,555 DEBUG [main] SequenceGenerator:127 - Sequence identifier generated: BasicHolder[java.lang.Integer[23]]
12:54:05,555 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,555 DEBUG [main] AbstractSaveEventListener:130 - Generated identifier: 23, using strategy: org.hibernate.id.SequenceHiLoGenerator
12:54:05,556 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,556 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,556 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 1 insertions, 0 updates, 0 deletions to 4 objects
12:54:05,556 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
12:54:05,556 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,556 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisPredicate{language=0, id=23, content=predicate content}
12:54:05,556 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTarget{idScheme=testing 23, lastChanged=2019-04-24 12:54:05.546190049, testAssertions=null, lastModifierId=null, language=null, id=23, type=null, content=null}
12:54:05,556 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisNormativeSource{derivedSourceItems=null, interpretation=null, textSourceItems=null, lastChanged=2019-04-24 12:54:05.554121876, refSourceItems=null, testAssertions=null, lastModifierId=null, comment=null, id=23, content=null}
12:54:05,556 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,557 DEBUG [main] SQL:104 - 
    insert 
    into
        am_oasis_normative_source
        (last_changed, last_modifier_id, comment_id, content, interpretation_id, id) 
    values
        (?, ?, ?, ?, ?, ?)
12:54:05,557 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,557 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,557 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,558 DEBUG [main] UpdateTimestampsCache:88 - Pre-invalidating space [am_oasis_normative_source], timestamp: 6373799139565568
12:54:05,558 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_normative_source value: 6373799139565568
12:54:05,558 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,558 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,558 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,558 DEBUG [main] AbstractTransactionImpl:173 - committing
12:54:05,558 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,559 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,559 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,559 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,559 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 0 insertions, 0 updates, 0 deletions to 4 objects
12:54:05,559 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
12:54:05,559 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,559 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisPredicate{language=0, id=23, content=predicate content}
12:54:05,559 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTarget{idScheme=testing 23, lastChanged=2019-04-24 12:54:05.546190049, testAssertions=null, lastModifierId=null, language=null, id=23, type=null, content=null}
12:54:05,559 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisNormativeSource{derivedSourceItems=null, interpretation=null, textSourceItems=null, lastChanged=2019-04-24 12:54:05.554121876, refSourceItems=null, testAssertions=null, lastModifierId=null, comment=null, id=23, content=null}
12:54:05,559 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,560 DEBUG [main] JdbcTransaction:113 - committed JDBC Connection
12:54:05,560 DEBUG [main] JdbcTransaction:126 - re-enabling autocommit
12:54:05,560 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,561 DEBUG [main] UpdateTimestampsCache:125 - Invalidating space [am_oasis_normative_source], timestamp: 6373798893817856
12:54:05,561 DEBUG [instances.data] Segment:779 - fault removed 0 from heap
12:54:05,561 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_normative_source value: 6373798893817856
12:54:05,561 DEBUG [instances.data] Segment:796 - fault added 0 on disk
12:54:05,561 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,561 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,561 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,561 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,561 DEBUG [main] AbstractTransactionImpl:158 - begin
12:54:05,561 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,562 DEBUG [main] JdbcTransaction:69 - initial autocommit status: true
12:54:05,562 DEBUG [main] JdbcTransaction:71 - disabling autocommit
12:54:05,562 DEBUG [main] SQL:104 - 
    select
        nextval ('am_oasis_test_assertion_id_seq')
12:54:05,562 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,562 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,563 DEBUG [main] SequenceGenerator:127 - Sequence identifier generated: BasicHolder[java.lang.Integer[23]]
12:54:05,563 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,563 DEBUG [main] AbstractSaveEventListener:130 - Generated identifier: 23, using strategy: org.hibernate.id.SequenceHiLoGenerator
12:54:05,563 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,563 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,564 DEBUG [main] Collections:190 - Collection found: [net.ihe.gazelle.oasis.testassertion.OasisTestAssertion.tags#23], was: [<unreferenced>] (initialized)
12:54:05,564 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 1 insertions, 0 updates, 0 deletions to 5 objects
12:54:05,564 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 1 (re)creations, 0 updates, 0 removals to 1 collections
12:54:05,564 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,564 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisPredicate{language=0, id=23, content=predicate content}
12:54:05,564 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTarget{idScheme=testing 23, lastChanged=2019-04-24 12:54:05.546190049, testAssertions=null, lastModifierId=null, language=null, id=23, type=null, content=null}
12:54:05,564 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisNormativeSource{derivedSourceItems=null, interpretation=null, textSourceItems=null, lastChanged=2019-04-24 12:54:05.554121876, refSourceItems=null, testAssertions=null, lastModifierId=null, comment=null, id=23, content=null}
12:54:05,564 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTestAssertion{mbv=null, normativeSource=net.ihe.gazelle.oasis.testassertion.OasisNormativeSource#23, pageNumber=null, coverageCount=null, testable=true, description=null, otherTagOnAssertion=null, testSteps=null, predicate=net.ihe.gazelle.oasis.testassertion.OasisPredicate#23, assertionId=Assertion-id23, tfRulesCoverageCount=null, appliesToCount=null, lastModifierId=null, id=23, tfTransactions=null, tfIntegrationProfiles=null, variables=null, lastChanged=2019-04-24 12:54:05.561826955, prerequisite=null, tfActors=null, tfAIPOs=null, tags=[], target=net.ihe.gazelle.oasis.testassertion.OasisTarget#23, mbvCoverageCount=null, tests=null, tfAuditMessages=null, prescription=null, testsCoverageCount=null, tfStandards=null, comment=null, scopes=null, tfRules=null, status=null}
12:54:05,564 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,565 DEBUG [main] BooleanConverter:336 - Setting default value: false
12:54:05,565 DEBUG [main] BooleanConverter:127 - Converting 'Boolean' value 'false' to type 'Boolean'
12:54:05,566 DEBUG [main] BooleanConverter:149 -     No conversion required, value is already a Boolean
12:54:05,566 DEBUG [main] ByteConverter:336 - Setting default value: 0
12:54:05,566 DEBUG [main] ByteConverter:127 - Converting 'Integer' value '0' to type 'Byte'
12:54:05,566 DEBUG [main] ByteConverter:158 -     Converted to Byte value '0'
12:54:05,566 DEBUG [main] CharacterConverter:336 - Setting default value:  
12:54:05,566 DEBUG [main] CharacterConverter:127 - Converting 'Character' value ' ' to type 'Character'
12:54:05,566 DEBUG [main] CharacterConverter:149 -     No conversion required, value is already a Character
12:54:05,567 DEBUG [main] DoubleConverter:336 - Setting default value: 0
12:54:05,567 DEBUG [main] DoubleConverter:127 - Converting 'Integer' value '0' to type 'Double'
12:54:05,567 DEBUG [main] DoubleConverter:158 -     Converted to Double value '0.0'
12:54:05,567 DEBUG [main] FloatConverter:336 - Setting default value: 0
12:54:05,567 DEBUG [main] FloatConverter:127 - Converting 'Integer' value '0' to type 'Float'
12:54:05,567 DEBUG [main] FloatConverter:158 -     Converted to Float value '0.0'
12:54:05,567 DEBUG [main] IntegerConverter:336 - Setting default value: 0
12:54:05,567 DEBUG [main] IntegerConverter:127 - Converting 'Integer' value '0' to type 'Integer'
12:54:05,568 DEBUG [main] IntegerConverter:149 -     No conversion required, value is already a Integer
12:54:05,568 DEBUG [main] LongConverter:336 - Setting default value: 0
12:54:05,568 DEBUG [main] LongConverter:127 - Converting 'Integer' value '0' to type 'Long'
12:54:05,568 DEBUG [main] LongConverter:158 -     Converted to Long value '0'
12:54:05,568 DEBUG [main] ShortConverter:336 - Setting default value: 0
12:54:05,568 DEBUG [main] ShortConverter:127 - Converting 'Integer' value '0' to type 'Short'
12:54:05,568 DEBUG [main] ShortConverter:158 -     Converted to Short value '0'
12:54:05,569 DEBUG [main] BigDecimalConverter:336 - Setting default value: 0.0
12:54:05,569 DEBUG [main] BigDecimalConverter:127 - Converting 'BigDecimal' value '0.0' to type 'BigDecimal'
12:54:05,569 DEBUG [main] BigDecimalConverter:149 -     No conversion required, value is already a BigDecimal
12:54:05,569 DEBUG [main] BigIntegerConverter:336 - Setting default value: 0
12:54:05,569 DEBUG [main] BigIntegerConverter:127 - Converting 'BigInteger' value '0' to type 'BigInteger'
12:54:05,569 DEBUG [main] BigIntegerConverter:149 -     No conversion required, value is already a BigInteger
12:54:05,570 DEBUG [main] BooleanConverter:336 - Setting default value: false
12:54:05,570 DEBUG [main] BooleanConverter:127 - Converting 'Boolean' value 'false' to type 'Boolean'
12:54:05,570 DEBUG [main] BooleanConverter:149 -     No conversion required, value is already a Boolean
12:54:05,570 DEBUG [main] ByteConverter:336 - Setting default value: 0
12:54:05,570 DEBUG [main] ByteConverter:127 - Converting 'Integer' value '0' to type 'Byte'
12:54:05,570 DEBUG [main] ByteConverter:158 -     Converted to Byte value '0'
12:54:05,570 DEBUG [main] CharacterConverter:336 - Setting default value:  
12:54:05,570 DEBUG [main] CharacterConverter:127 - Converting 'Character' value ' ' to type 'Character'
12:54:05,571 DEBUG [main] CharacterConverter:149 -     No conversion required, value is already a Character
12:54:05,571 DEBUG [main] DoubleConverter:336 - Setting default value: 0
12:54:05,571 DEBUG [main] DoubleConverter:127 - Converting 'Integer' value '0' to type 'Double'
12:54:05,571 DEBUG [main] DoubleConverter:158 -     Converted to Double value '0.0'
12:54:05,571 DEBUG [main] FloatConverter:336 - Setting default value: 0
12:54:05,571 DEBUG [main] FloatConverter:127 - Converting 'Integer' value '0' to type 'Float'
12:54:05,571 DEBUG [main] FloatConverter:158 -     Converted to Float value '0.0'
12:54:05,572 DEBUG [main] IntegerConverter:336 - Setting default value: 0
12:54:05,572 DEBUG [main] IntegerConverter:127 - Converting 'Integer' value '0' to type 'Integer'
12:54:05,572 DEBUG [main] IntegerConverter:149 -     No conversion required, value is already a Integer
12:54:05,572 DEBUG [main] LongConverter:336 - Setting default value: 0
12:54:05,572 DEBUG [main] LongConverter:127 - Converting 'Integer' value '0' to type 'Long'
12:54:05,572 DEBUG [main] LongConverter:158 -     Converted to Long value '0'
12:54:05,572 DEBUG [main] ShortConverter:336 - Setting default value: 0
12:54:05,572 DEBUG [main] ShortConverter:127 - Converting 'Integer' value '0' to type 'Short'
12:54:05,573 DEBUG [main] ShortConverter:158 -     Converted to Short value '0'
12:54:05,573 DEBUG [main] StringConverter:336 - Setting default value: 
12:54:05,573 DEBUG [main] StringConverter:127 - Converting 'String' value '' to type 'String'
12:54:05,573 DEBUG [main] ArrayConverter:336 - Setting default value: [Z@32fa956b
12:54:05,573 DEBUG [main] ArrayConverter:127 - Converting 'boolean[]' value '[Z@32fa956b' to type 'boolean[]'
12:54:05,573 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a boolean[]
12:54:05,573 DEBUG [main] ArrayConverter:336 - Setting default value: [B@71bb6009
12:54:05,573 DEBUG [main] ArrayConverter:127 - Converting 'byte[]' value '[B@71bb6009' to type 'byte[]'
12:54:05,574 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a byte[]
12:54:05,574 DEBUG [main] ArrayConverter:336 - Setting default value: [C@232bfb3c
12:54:05,574 DEBUG [main] ArrayConverter:127 - Converting 'char[]' value '[C@232bfb3c' to type 'char[]'
12:54:05,574 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a char[]
12:54:05,574 DEBUG [main] ArrayConverter:336 - Setting default value: [D@16337c8e
12:54:05,574 DEBUG [main] ArrayConverter:127 - Converting 'double[]' value '[D@16337c8e' to type 'double[]'
12:54:05,574 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a double[]
12:54:05,574 DEBUG [main] ArrayConverter:336 - Setting default value: [F@3b0471a5
12:54:05,575 DEBUG [main] ArrayConverter:127 - Converting 'float[]' value '[F@3b0471a5' to type 'float[]'
12:54:05,575 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a float[]
12:54:05,575 DEBUG [main] ArrayConverter:336 - Setting default value: [I@7aac05e2
12:54:05,575 DEBUG [main] ArrayConverter:127 - Converting 'int[]' value '[I@7aac05e2' to type 'int[]'
12:54:05,575 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a int[]
12:54:05,575 DEBUG [main] ArrayConverter:336 - Setting default value: [J@4867e76b
12:54:05,575 DEBUG [main] ArrayConverter:127 - Converting 'long[]' value '[J@4867e76b' to type 'long[]'
12:54:05,575 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a long[]
12:54:05,576 DEBUG [main] ArrayConverter:336 - Setting default value: [S@4b48be5c
12:54:05,576 DEBUG [main] ArrayConverter:127 - Converting 'short[]' value '[S@4b48be5c' to type 'short[]'
12:54:05,576 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a short[]
12:54:05,576 DEBUG [main] ArrayConverter:336 - Setting default value: [Ljava.math.BigDecimal;@1ef6977b
12:54:05,576 DEBUG [main] ArrayConverter:127 - Converting 'BigDecimal[]' value '[Ljava.math.BigDecimal;@1ef6977b' to type 'BigDecimal[]'
12:54:05,576 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a BigDecimal[]
12:54:05,576 DEBUG [main] ArrayConverter:336 - Setting default value: [Ljava.math.BigInteger;@41cfcbb5
12:54:05,576 DEBUG [main] ArrayConverter:127 - Converting 'BigInteger[]' value '[Ljava.math.BigInteger;@41cfcbb5' to type 'BigInteger[]'
12:54:05,577 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a BigInteger[]
12:54:05,577 DEBUG [main] ArrayConverter:336 - Setting default value: [Ljava.lang.Boolean;@29cd48bd
12:54:05,577 DEBUG [main] ArrayConverter:127 - Converting 'Boolean[]' value '[Ljava.lang.Boolean;@29cd48bd' to type 'Boolean[]'
12:54:05,577 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a Boolean[]
12:54:05,577 DEBUG [main] ArrayConverter:336 - Setting default value: [Ljava.lang.Byte;@34d776eb
12:54:05,577 DEBUG [main] ArrayConverter:127 - Converting 'Byte[]' value '[Ljava.lang.Byte;@34d776eb' to type 'Byte[]'
12:54:05,577 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a Byte[]
12:54:05,577 DEBUG [main] ArrayConverter:336 - Setting default value: [Ljava.lang.Character;@d15f98a
12:54:05,578 DEBUG [main] ArrayConverter:127 - Converting 'Character[]' value '[Ljava.lang.Character;@d15f98a' to type 'Character[]'
12:54:05,578 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a Character[]
12:54:05,578 DEBUG [main] ArrayConverter:336 - Setting default value: [Ljava.lang.Double;@8d40f07
12:54:05,578 DEBUG [main] ArrayConverter:127 - Converting 'Double[]' value '[Ljava.lang.Double;@8d40f07' to type 'Double[]'
12:54:05,578 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a Double[]
12:54:05,578 DEBUG [main] ArrayConverter:336 - Setting default value: [Ljava.lang.Float;@49d5b651
12:54:05,578 DEBUG [main] ArrayConverter:127 - Converting 'Float[]' value '[Ljava.lang.Float;@49d5b651' to type 'Float[]'
12:54:05,578 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a Float[]
12:54:05,579 DEBUG [main] ArrayConverter:336 - Setting default value: [Ljava.lang.Integer;@6d4bdb75
12:54:05,579 DEBUG [main] ArrayConverter:127 - Converting 'Integer[]' value '[Ljava.lang.Integer;@6d4bdb75' to type 'Integer[]'
12:54:05,579 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a Integer[]
12:54:05,579 DEBUG [main] ArrayConverter:336 - Setting default value: [Ljava.lang.Long;@5bd585a5
12:54:05,579 DEBUG [main] ArrayConverter:127 - Converting 'Long[]' value '[Ljava.lang.Long;@5bd585a5' to type 'Long[]'
12:54:05,579 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a Long[]
12:54:05,579 DEBUG [main] ArrayConverter:336 - Setting default value: [Ljava.lang.Short;@3d0c88f4
12:54:05,580 DEBUG [main] ArrayConverter:127 - Converting 'Short[]' value '[Ljava.lang.Short;@3d0c88f4' to type 'Short[]'
12:54:05,580 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a Short[]
12:54:05,580 DEBUG [main] ArrayConverter:336 - Setting default value: [Ljava.lang.String;@5d41b929
12:54:05,580 DEBUG [main] ArrayConverter:127 - Converting 'String[]' value '[Ljava.lang.String;@5d41b929' to type 'String[]'
12:54:05,580 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a String[]
12:54:05,580 DEBUG [main] ArrayConverter:336 - Setting default value: [Ljava.lang.Class;@797a5b31
12:54:05,580 DEBUG [main] ArrayConverter:127 - Converting 'Class[]' value '[Ljava.lang.Class;@797a5b31' to type 'Class[]'
12:54:05,581 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a Class[]
12:54:05,581 DEBUG [main] ArrayConverter:336 - Setting default value: [Ljava.util.Date;@732ffb6a
12:54:05,581 DEBUG [main] ArrayConverter:127 - Converting 'Date[]' value '[Ljava.util.Date;@732ffb6a' to type 'Date[]'
12:54:05,581 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a Date[]
12:54:05,581 DEBUG [main] ArrayConverter:336 - Setting default value: [Ljava.util.Calendar;@4ce66169
12:54:05,581 DEBUG [main] ArrayConverter:127 - Converting 'Calendar[]' value '[Ljava.util.Calendar;@4ce66169' to type 'Calendar[]'
12:54:05,581 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a Calendar[]
12:54:05,582 DEBUG [main] ArrayConverter:336 - Setting default value: [Ljava.io.File;@72e4905c
12:54:05,582 DEBUG [main] ArrayConverter:127 - Converting 'java.io.File[]' value '[Ljava.io.File;@72e4905c' to type 'java.io.File[]'
12:54:05,582 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a java.io.File[]
12:54:05,582 DEBUG [main] ArrayConverter:336 - Setting default value: [Ljava.sql.Date;@16441c13
12:54:05,582 DEBUG [main] ArrayConverter:127 - Converting 'java.sql.Date[]' value '[Ljava.sql.Date;@16441c13' to type 'java.sql.Date[]'
12:54:05,582 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a java.sql.Date[]
12:54:05,582 DEBUG [main] ArrayConverter:336 - Setting default value: [Ljava.sql.Time;@405a296e
12:54:05,583 DEBUG [main] ArrayConverter:127 - Converting 'java.sql.Time[]' value '[Ljava.sql.Time;@405a296e' to type 'java.sql.Time[]'
12:54:05,583 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a java.sql.Time[]
12:54:05,583 DEBUG [main] ArrayConverter:336 - Setting default value: [Ljava.sql.Timestamp;@293ccbdd
12:54:05,583 DEBUG [main] ArrayConverter:127 - Converting 'java.sql.Timestamp[]' value '[Ljava.sql.Timestamp;@293ccbdd' to type 'java.sql.Timestamp[]'
12:54:05,583 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a java.sql.Timestamp[]
12:54:05,583 DEBUG [main] ArrayConverter:336 - Setting default value: [Ljava.net.URL;@54a04eae
12:54:05,583 DEBUG [main] ArrayConverter:127 - Converting 'java.net.URL[]' value '[Ljava.net.URL;@54a04eae' to type 'java.net.URL[]'
12:54:05,583 DEBUG [main] ArrayConverter:149 -     No conversion required, value is already a java.net.URL[]
12:54:05,584 DEBUG [main] SQL:104 - 
    insert 
    into
        am_oasis_test_assertion
        (last_changed, last_modifier_id, applies_to_count, assertion_id, comment, coverage_count, description_id, mbv_coverage_count, normative_source_id, other_tag_on_assertion, page_number, predicate_id, prerequisite_id, prescription_id, status, target_id, testable, tests_coverage_count, tf_rules_coverage_count, id) 
    values
        (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
12:54:05,584 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,584 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,585 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,585 DEBUG [main] UpdateTimestampsCache:88 - Pre-invalidating space [am_oasis_test_assertion], timestamp: 6373799139676160
12:54:05,585 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_test_assertion value: 6373799139676160
12:54:05,585 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,586 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,586 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,586 DEBUG [main] AbstractCollectionPersister:1201 - Inserting collection: [net.ihe.gazelle.oasis.testassertion.OasisTestAssertion.tags#23]
12:54:05,586 DEBUG [main] AbstractCollectionPersister:1288 - Collection was empty
12:54:05,586 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,586 DEBUG [main] UpdateTimestampsCache:88 - Pre-invalidating space [am_oasis_test_assertion_tag], timestamp: 6373799139680256
12:54:05,586 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,587 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_test_assertion_tag value: 6373799139680256
12:54:05,587 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,587 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,587 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,587 DEBUG [main] AbstractTransactionImpl:173 - committing
12:54:05,587 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,587 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,587 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,588 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,588 DEBUG [main] Collections:190 - Collection found: [net.ihe.gazelle.oasis.testassertion.OasisTestAssertion.tags#23], was: [net.ihe.gazelle.oasis.testassertion.OasisTestAssertion.tags#23] (initialized)
12:54:05,588 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 0 insertions, 0 updates, 0 deletions to 5 objects
12:54:05,588 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 0 (re)creations, 0 updates, 0 removals to 1 collections
12:54:05,588 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,588 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisPredicate{language=0, id=23, content=predicate content}
12:54:05,588 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTarget{idScheme=testing 23, lastChanged=2019-04-24 12:54:05.546190049, testAssertions=null, lastModifierId=null, language=null, id=23, type=null, content=null}
12:54:05,588 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisNormativeSource{derivedSourceItems=null, interpretation=null, textSourceItems=null, lastChanged=2019-04-24 12:54:05.554121876, refSourceItems=null, testAssertions=null, lastModifierId=null, comment=null, id=23, content=null}
12:54:05,588 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTestAssertion{mbv=null, normativeSource=net.ihe.gazelle.oasis.testassertion.OasisNormativeSource#23, pageNumber=null, coverageCount=null, testable=true, description=null, otherTagOnAssertion=null, testSteps=null, predicate=net.ihe.gazelle.oasis.testassertion.OasisPredicate#23, assertionId=Assertion-id23, tfRulesCoverageCount=null, appliesToCount=null, lastModifierId=null, id=23, tfTransactions=null, tfIntegrationProfiles=null, variables=null, lastChanged=2019-04-24 12:54:05.561826955, prerequisite=null, tfActors=null, tfAIPOs=null, tags=[], target=net.ihe.gazelle.oasis.testassertion.OasisTarget#23, mbvCoverageCount=null, tests=null, tfAuditMessages=null, prescription=null, testsCoverageCount=null, tfStandards=null, comment=null, scopes=null, tfRules=null, status=null}
12:54:05,589 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,589 DEBUG [main] JdbcTransaction:113 - committed JDBC Connection
12:54:05,589 DEBUG [main] JdbcTransaction:126 - re-enabling autocommit
12:54:05,589 DEBUG [main] UpdateTimestampsCache:125 - Invalidating space [am_oasis_test_assertion], timestamp: 6373798893932544
12:54:05,589 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_test_assertion value: 6373798893932544
12:54:05,590 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,590 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,590 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,590 DEBUG [main] UpdateTimestampsCache:125 - Invalidating space [am_oasis_test_assertion_tag], timestamp: 6373798893932544
12:54:05,590 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,590 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_test_assertion_tag value: 6373798893932544
12:54:05,590 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,590 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,591 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,591 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,591 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,591 DEBUG [main] AbstractTransactionImpl:158 - begin
12:54:05,591 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,591 DEBUG [main] JdbcTransaction:69 - initial autocommit status: true
12:54:05,591 DEBUG [main] JdbcTransaction:71 - disabling autocommit
12:54:05,591 DEBUG [main] SQL:104 - 
    select
        nextval ('am_assertions_links_id_seq')
12:54:05,591 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,592 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,592 DEBUG [main] SequenceGenerator:127 - Sequence identifier generated: BasicHolder[java.lang.Integer[17]]
12:54:05,592 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,592 DEBUG [main] AbstractSaveEventListener:130 - Generated identifier: 17, using strategy: org.hibernate.id.SequenceHiLoGenerator
12:54:05,592 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,593 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,593 DEBUG [main] Collections:190 - Collection found: [net.ihe.gazelle.oasis.testassertion.OasisTestAssertion.tags#23], was: [net.ihe.gazelle.oasis.testassertion.OasisTestAssertion.tags#23] (initialized)
12:54:05,593 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 1 insertions, 0 updates, 0 deletions to 6 objects
12:54:05,593 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 0 (re)creations, 0 updates, 0 removals to 1 collections
12:54:05,593 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,593 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.AssertionLinkedToTest{linkedEntityProvider=null, deprecated=false, linkedEntityKeyword=0, linkedEntityName=null, assertion=net.ihe.gazelle.oasis.testassertion.OasisTestAssertion#23, id=17, linkedEntityPermalink=null, linkedEntity=null}
12:54:05,593 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisPredicate{language=0, id=23, content=predicate content}
12:54:05,593 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTarget{idScheme=testing 23, lastChanged=2019-04-24 12:54:05.546190049, testAssertions=null, lastModifierId=null, language=null, id=23, type=null, content=null}
12:54:05,593 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisNormativeSource{derivedSourceItems=null, interpretation=null, textSourceItems=null, lastChanged=2019-04-24 12:54:05.554121876, refSourceItems=null, testAssertions=null, lastModifierId=null, comment=null, id=23, content=null}
12:54:05,593 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTestAssertion{mbv=null, normativeSource=net.ihe.gazelle.oasis.testassertion.OasisNormativeSource#23, pageNumber=null, coverageCount=null, testable=true, description=null, otherTagOnAssertion=null, testSteps=null, predicate=net.ihe.gazelle.oasis.testassertion.OasisPredicate#23, assertionId=Assertion-id23, tfRulesCoverageCount=null, appliesToCount=null, lastModifierId=null, id=23, tfTransactions=null, tfIntegrationProfiles=null, variables=null, lastChanged=2019-04-24 12:54:05.561826955, prerequisite=null, tfActors=null, tfAIPOs=null, tags=[], target=net.ihe.gazelle.oasis.testassertion.OasisTarget#23, mbvCoverageCount=null, tests=null, tfAuditMessages=null, prescription=null, testsCoverageCount=null, tfStandards=null, comment=null, scopes=null, tfRules=null, status=null}
12:54:05,594 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,594 DEBUG [main] SQL:104 - 
    insert 
    into
        am_assertions_links
        (deprecated, linked_entity_keyword, linked_entity_name, linked_entity_permalink, linked_entity_provider, assertion_id, linked_entity, id) 
    values
        (?, ?, ?, ?, ?, ?, 'TEST', ?)
12:54:05,594 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,594 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,595 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,595 DEBUG [main] UpdateTimestampsCache:88 - Pre-invalidating space [am_assertions_links], timestamp: 6373799139717120
12:54:05,595 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_assertions_links value: 6373799139717120
12:54:05,595 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,595 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,595 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,595 DEBUG [main] AbstractTransactionImpl:173 - committing
12:54:05,596 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,596 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,596 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,596 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,596 DEBUG [main] Collections:190 - Collection found: [net.ihe.gazelle.oasis.testassertion.OasisTestAssertion.tags#23], was: [net.ihe.gazelle.oasis.testassertion.OasisTestAssertion.tags#23] (initialized)
12:54:05,596 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 0 insertions, 0 updates, 0 deletions to 6 objects
12:54:05,596 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 0 (re)creations, 0 updates, 0 removals to 1 collections
12:54:05,596 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,596 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.AssertionLinkedToTest{linkedEntityProvider=null, deprecated=false, linkedEntityKeyword=0, linkedEntityName=null, assertion=net.ihe.gazelle.oasis.testassertion.OasisTestAssertion#23, id=17, linkedEntityPermalink=null, linkedEntity=null}
12:54:05,597 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisPredicate{language=0, id=23, content=predicate content}
12:54:05,597 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTarget{idScheme=testing 23, lastChanged=2019-04-24 12:54:05.546190049, testAssertions=null, lastModifierId=null, language=null, id=23, type=null, content=null}
12:54:05,597 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisNormativeSource{derivedSourceItems=null, interpretation=null, textSourceItems=null, lastChanged=2019-04-24 12:54:05.554121876, refSourceItems=null, testAssertions=null, lastModifierId=null, comment=null, id=23, content=null}
12:54:05,597 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTestAssertion{mbv=null, normativeSource=net.ihe.gazelle.oasis.testassertion.OasisNormativeSource#23, pageNumber=null, coverageCount=null, testable=true, description=null, otherTagOnAssertion=null, testSteps=null, predicate=net.ihe.gazelle.oasis.testassertion.OasisPredicate#23, assertionId=Assertion-id23, tfRulesCoverageCount=null, appliesToCount=null, lastModifierId=null, id=23, tfTransactions=null, tfIntegrationProfiles=null, variables=null, lastChanged=2019-04-24 12:54:05.561826955, prerequisite=null, tfActors=null, tfAIPOs=null, tags=[], target=net.ihe.gazelle.oasis.testassertion.OasisTarget#23, mbvCoverageCount=null, tests=null, tfAuditMessages=null, prescription=null, testsCoverageCount=null, tfStandards=null, comment=null, scopes=null, tfRules=null, status=null}
12:54:05,597 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,597 DEBUG [main] JdbcTransaction:113 - committed JDBC Connection
12:54:05,598 DEBUG [main] JdbcTransaction:126 - re-enabling autocommit
12:54:05,598 DEBUG [main] UpdateTimestampsCache:125 - Invalidating space [am_assertions_links], timestamp: 6373798893969408
12:54:05,598 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_assertions_links value: 6373798893969408
12:54:05,598 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,598 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,598 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,598 DEBUG [main] AbstractTransactionImpl:158 - begin
12:54:05,598 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,599 DEBUG [main] JdbcTransaction:69 - initial autocommit status: true
12:54:05,599 DEBUG [main] JdbcTransaction:71 - disabling autocommit
12:54:05,599 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,599 DEBUG [main] StandardQueryCache:138 - Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache
12:54:05,599 DEBUG [main] EhcacheGeneralDataRegion:69 - key: sql: select distinct assertionl0_.id as id2_5_, assertionl0_.deprecated as deprecat3_5_, assertionl0_.linked_entity as linked_e1_5_, assertionl0_.linked_entity_keyword as linked_e4_5_, assertionl0_.linked_entity_name as linked_e5_5_, assertionl0_.linked_entity_permalink as linked_e6_5_, assertionl0_.linked_entity_provider as linked_e7_5_, assertionl0_.assertion_id as assertio8_5_ from am_assertions_links assertionl0_ where assertionl0_.linked_entity='TEST' and assertionl0_.linked_entity_keyword=?; parameters: ; named parameters: {restriction_0=0}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2
12:54:05,599 DEBUG [main] StandardQueryCache:212 - Checking query spaces are up-to-date: [am_assertions_links]
12:54:05,599 DEBUG [main] EhcacheGeneralDataRegion:69 - key: am_assertions_links
12:54:05,600 DEBUG [main] UpdateTimestampsCache:175 - [am_assertions_links] last update timestamp: 6373798893969408, result set timestamp: 6373798893465600
12:54:05,600 DEBUG [main] StandardQueryCache:151 - Cached query results were not up-to-date
12:54:05,600 DEBUG [main] SQL:104 - 
    select
        distinct assertionl0_.id as id2_5_,
        assertionl0_.deprecated as deprecat3_5_,
        assertionl0_.linked_entity as linked_e1_5_,
        assertionl0_.linked_entity_keyword as linked_e4_5_,
        assertionl0_.linked_entity_name as linked_e5_5_,
        assertionl0_.linked_entity_permalink as linked_e6_5_,
        assertionl0_.linked_entity_provider as linked_e7_5_,
        assertionl0_.assertion_id as assertio8_5_ 
    from
        am_assertions_links assertionl0_ 
    where
        assertionl0_.linked_entity='TEST' 
        and assertionl0_.linked_entity_keyword=?
12:54:05,600 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,600 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,601 DEBUG [main] Loader:948 - Result set row: 0
12:54:05,601 DEBUG [main] Loader:1480 - Result row: EntityKey[net.ihe.gazelle.oasis.testassertion.AssertionLinkedToTest#17]
12:54:05,601 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,601 DEBUG [main] StandardQueryCache:104 - Caching query results in region: org.hibernate.cache.internal.StandardQueryCache; timestamp=6373798893981696
12:54:05,601 DEBUG [main] EhcacheGeneralDataRegion:100 - key: sql: select distinct assertionl0_.id as id2_5_, assertionl0_.deprecated as deprecat3_5_, assertionl0_.linked_entity as linked_e1_5_, assertionl0_.linked_entity_keyword as linked_e4_5_, assertionl0_.linked_entity_name as linked_e5_5_, assertionl0_.linked_entity_permalink as linked_e6_5_, assertionl0_.linked_entity_provider as linked_e7_5_, assertionl0_.assertion_id as assertio8_5_ from am_assertions_links assertionl0_ where assertionl0_.linked_entity='TEST' and assertionl0_.linked_entity_keyword=?; parameters: ; named parameters: {restriction_0=0}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2 value: [6373798893981696, 17]
12:54:05,602 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,602 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,602 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,603 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,603 DEBUG [org%002ehibernate%002ecache%002einternal%002e%0053tandard%0051uery%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,603 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,603 DEBUG [org%002ehibernate%002ecache%002einternal%002e%0053tandard%0051uery%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,603 DEBUG [main] Collections:190 - Collection found: [net.ihe.gazelle.oasis.testassertion.OasisTestAssertion.tags#23], was: [net.ihe.gazelle.oasis.testassertion.OasisTestAssertion.tags#23] (initialized)
12:54:05,603 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 0 insertions, 0 updates, 0 deletions to 6 objects
12:54:05,603 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 0 (re)creations, 0 updates, 0 removals to 1 collections
12:54:05,603 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,603 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.AssertionLinkedToTest{linkedEntityProvider=null, deprecated=false, linkedEntityKeyword=0, linkedEntityName=null, assertion=net.ihe.gazelle.oasis.testassertion.OasisTestAssertion#23, id=17, linkedEntityPermalink=null, linkedEntity=null}
12:54:05,604 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisPredicate{language=0, id=23, content=predicate content}
12:54:05,604 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTarget{idScheme=testing 23, lastChanged=2019-04-24 12:54:05.546190049, testAssertions=null, lastModifierId=null, language=null, id=23, type=null, content=null}
12:54:05,604 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisNormativeSource{derivedSourceItems=null, interpretation=null, textSourceItems=null, lastChanged=2019-04-24 12:54:05.554121876, refSourceItems=null, testAssertions=null, lastModifierId=null, comment=null, id=23, content=null}
12:54:05,604 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTestAssertion{mbv=null, normativeSource=net.ihe.gazelle.oasis.testassertion.OasisNormativeSource#23, pageNumber=null, coverageCount=null, testable=true, description=null, otherTagOnAssertion=null, testSteps=null, predicate=net.ihe.gazelle.oasis.testassertion.OasisPredicate#23, assertionId=Assertion-id23, tfRulesCoverageCount=null, appliesToCount=null, lastModifierId=null, id=23, tfTransactions=null, tfIntegrationProfiles=null, variables=null, lastChanged=2019-04-24 12:54:05.561826955, prerequisite=null, tfActors=null, tfAIPOs=null, tags=[], target=net.ihe.gazelle.oasis.testassertion.OasisTarget#23, mbvCoverageCount=null, tests=null, tfAuditMessages=null, prescription=null, testsCoverageCount=null, tfStandards=null, comment=null, scopes=null, tfRules=null, status=null}
12:54:05,604 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,604 DEBUG [main] Loader:2133 - Loading entity: [net.ihe.gazelle.oasis.testassertion.AssertionLinkedToTest#17]
12:54:05,604 DEBUG [main] SQL:104 - 
    select
        assertionl0_.id as id2_5_0_,
        assertionl0_.deprecated as deprecat3_5_0_,
        assertionl0_.linked_entity as linked_e1_5_0_,
        assertionl0_.linked_entity_keyword as linked_e4_5_0_,
        assertionl0_.linked_entity_name as linked_e5_5_0_,
        assertionl0_.linked_entity_permalink as linked_e6_5_0_,
        assertionl0_.linked_entity_provider as linked_e7_5_0_,
        assertionl0_.assertion_id as assertio8_5_0_ 
    from
        am_assertions_links assertionl0_ 
    where
        assertionl0_.id=? 
        and assertionl0_.linked_entity='TEST'
12:54:05,604 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,605 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,605 DEBUG [main] Loader:948 - Result set row: 0
12:54:05,605 DEBUG [main] Loader:1480 - Result row: EntityKey[net.ihe.gazelle.oasis.testassertion.AssertionLinkedToTest#17]
12:54:05,605 DEBUG [main] TwoPhaseLoad:158 - Resolving associations for [net.ihe.gazelle.oasis.testassertion.AssertionLinkedToTest#17]
12:54:05,606 DEBUG [main] TwoPhaseLoad:283 - Done materializing entity [net.ihe.gazelle.oasis.testassertion.AssertionLinkedToTest#17]
12:54:05,606 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,606 DEBUG [main] Loader:2157 - Done entity load
12:54:05,606 DEBUG [main] StandardQueryCache:138 - Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache
12:54:05,606 DEBUG [main] EhcacheGeneralDataRegion:69 - key: sql: select distinct assertionl0_.id as id2_5_, assertionl0_.deprecated as deprecat3_5_, assertionl0_.linked_entity as linked_e1_5_, assertionl0_.linked_entity_keyword as linked_e4_5_, assertionl0_.linked_entity_name as linked_e5_5_, assertionl0_.linked_entity_permalink as linked_e6_5_, assertionl0_.linked_entity_provider as linked_e7_5_, assertionl0_.assertion_id as assertio8_5_ from am_assertions_links assertionl0_ where assertionl0_.linked_entity='TEST'; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2
12:54:05,607 DEBUG [main] StandardQueryCache:212 - Checking query spaces are up-to-date: [am_assertions_links]
12:54:05,607 DEBUG [main] EhcacheGeneralDataRegion:69 - key: am_assertions_links
12:54:05,607 DEBUG [main] UpdateTimestampsCache:175 - [am_assertions_links] last update timestamp: 6373798893969408, result set timestamp: 6373798893502464
12:54:05,607 DEBUG [main] StandardQueryCache:151 - Cached query results were not up-to-date
12:54:05,607 DEBUG [main] SQL:104 - 
    select
        distinct assertionl0_.id as id2_5_,
        assertionl0_.deprecated as deprecat3_5_,
        assertionl0_.linked_entity as linked_e1_5_,
        assertionl0_.linked_entity_keyword as linked_e4_5_,
        assertionl0_.linked_entity_name as linked_e5_5_,
        assertionl0_.linked_entity_permalink as linked_e6_5_,
        assertionl0_.linked_entity_provider as linked_e7_5_,
        assertionl0_.assertion_id as assertio8_5_ 
    from
        am_assertions_links assertionl0_ 
    where
        assertionl0_.linked_entity='TEST'
12:54:05,607 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,607 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,608 DEBUG [main] Loader:948 - Result set row: 0
12:54:05,608 DEBUG [main] Loader:1480 - Result row: EntityKey[net.ihe.gazelle.oasis.testassertion.AssertionLinkedToTest#17]
12:54:05,608 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,608 DEBUG [main] StandardQueryCache:104 - Caching query results in region: org.hibernate.cache.internal.StandardQueryCache; timestamp=6373798894010368
12:54:05,608 DEBUG [main] EhcacheGeneralDataRegion:100 - key: sql: select distinct assertionl0_.id as id2_5_, assertionl0_.deprecated as deprecat3_5_, assertionl0_.linked_entity as linked_e1_5_, assertionl0_.linked_entity_keyword as linked_e4_5_, assertionl0_.linked_entity_name as linked_e5_5_, assertionl0_.linked_entity_permalink as linked_e6_5_, assertionl0_.linked_entity_provider as linked_e7_5_, assertionl0_.assertion_id as assertio8_5_ from am_assertions_links assertionl0_ where assertionl0_.linked_entity='TEST'; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2 value: [6373798894010368, 17]
12:54:05,608 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,609 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,609 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,609 DEBUG [org%002ehibernate%002ecache%002einternal%002e%0053tandard%0051uery%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,609 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,609 DEBUG [org%002ehibernate%002ecache%002einternal%002e%0053tandard%0051uery%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,609 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,610 DEBUG [main] Collections:190 - Collection found: [net.ihe.gazelle.oasis.testassertion.OasisTestAssertion.tags#23], was: [net.ihe.gazelle.oasis.testassertion.OasisTestAssertion.tags#23] (initialized)
12:54:05,610 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 0 insertions, 0 updates, 1 deletions to 6 objects
12:54:05,610 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 0 (re)creations, 0 updates, 0 removals to 1 collections
12:54:05,610 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,610 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.AssertionLinkedToTest{linkedEntityProvider=null, deprecated=false, linkedEntityKeyword=0, linkedEntityName=null, assertion=net.ihe.gazelle.oasis.testassertion.OasisTestAssertion#23, id=17, linkedEntityPermalink=null, linkedEntity=TEST}
12:54:05,610 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisPredicate{language=0, id=23, content=predicate content}
12:54:05,610 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTarget{idScheme=testing 23, lastChanged=2019-04-24 12:54:05.546190049, testAssertions=null, lastModifierId=null, language=null, id=23, type=null, content=null}
12:54:05,610 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisNormativeSource{derivedSourceItems=null, interpretation=null, textSourceItems=null, lastChanged=2019-04-24 12:54:05.554121876, refSourceItems=null, testAssertions=null, lastModifierId=null, comment=null, id=23, content=null}
12:54:05,611 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTestAssertion{mbv=null, normativeSource=net.ihe.gazelle.oasis.testassertion.OasisNormativeSource#23, pageNumber=null, coverageCount=null, testable=true, description=null, otherTagOnAssertion=null, testSteps=null, predicate=net.ihe.gazelle.oasis.testassertion.OasisPredicate#23, assertionId=Assertion-id23, tfRulesCoverageCount=null, appliesToCount=null, lastModifierId=null, id=23, tfTransactions=null, tfIntegrationProfiles=null, variables=null, lastChanged=2019-04-24 12:54:05.561826955, prerequisite=null, tfActors=null, tfAIPOs=null, tags=[], target=net.ihe.gazelle.oasis.testassertion.OasisTarget#23, mbvCoverageCount=null, tests=null, tfAuditMessages=null, prescription=null, testsCoverageCount=null, tfStandards=null, comment=null, scopes=null, tfRules=null, status=null}
12:54:05,611 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,611 DEBUG [main] SQL:104 - 
    delete 
    from
        am_assertions_links 
    where
        id=?
12:54:05,611 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,611 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,612 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,612 DEBUG [main] UpdateTimestampsCache:88 - Pre-invalidating space [am_assertions_links], timestamp: 6373799139786752
12:54:05,612 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_assertions_links value: 6373799139786752
12:54:05,612 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,612 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,612 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,612 DEBUG [main] AbstractTransactionImpl:173 - committing
12:54:05,612 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,613 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,613 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,613 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,613 DEBUG [main] Collections:190 - Collection found: [net.ihe.gazelle.oasis.testassertion.OasisTestAssertion.tags#23], was: [net.ihe.gazelle.oasis.testassertion.OasisTestAssertion.tags#23] (initialized)
12:54:05,613 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 0 insertions, 0 updates, 0 deletions to 5 objects
12:54:05,613 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 0 (re)creations, 0 updates, 0 removals to 1 collections
12:54:05,613 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,614 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisPredicate{language=0, id=23, content=predicate content}
12:54:05,614 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTarget{idScheme=testing 23, lastChanged=2019-04-24 12:54:05.546190049, testAssertions=null, lastModifierId=null, language=null, id=23, type=null, content=null}
12:54:05,614 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisNormativeSource{derivedSourceItems=null, interpretation=null, textSourceItems=null, lastChanged=2019-04-24 12:54:05.554121876, refSourceItems=null, testAssertions=null, lastModifierId=null, comment=null, id=23, content=null}
12:54:05,614 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTestAssertion{mbv=null, normativeSource=net.ihe.gazelle.oasis.testassertion.OasisNormativeSource#23, pageNumber=null, coverageCount=null, testable=true, description=null, otherTagOnAssertion=null, testSteps=null, predicate=net.ihe.gazelle.oasis.testassertion.OasisPredicate#23, assertionId=Assertion-id23, tfRulesCoverageCount=null, appliesToCount=null, lastModifierId=null, id=23, tfTransactions=null, tfIntegrationProfiles=null, variables=null, lastChanged=2019-04-24 12:54:05.561826955, prerequisite=null, tfActors=null, tfAIPOs=null, tags=[], target=net.ihe.gazelle.oasis.testassertion.OasisTarget#23, mbvCoverageCount=null, tests=null, tfAuditMessages=null, prescription=null, testsCoverageCount=null, tfStandards=null, comment=null, scopes=null, tfRules=null, status=null}
12:54:05,614 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,615 DEBUG [main] JdbcTransaction:113 - committed JDBC Connection
12:54:05,615 DEBUG [main] JdbcTransaction:126 - re-enabling autocommit
12:54:05,615 DEBUG [main] UpdateTimestampsCache:125 - Invalidating space [am_assertions_links], timestamp: 6373798894039040
12:54:05,615 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_assertions_links value: 6373798894039040
12:54:05,615 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,616 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,616 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,616 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,616 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,616 DEBUG [main] StandardQueryCache:138 - Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache
12:54:05,617 DEBUG [main] EhcacheGeneralDataRegion:69 - key: sql: select distinct oasistesta0_.id as id1_23_, oasistesta0_.last_changed as last_cha2_23_, oasistesta0_.last_modifier_id as last_mod3_23_, oasistesta0_.applies_to_count as applies_4_23_, oasistesta0_.assertion_id as assertio5_23_, oasistesta0_.comment as comment6_23_, oasistesta0_.coverage_count as coverage7_23_, oasistesta0_.description_id as descrip15_23_, oasistesta0_.mbv_coverage_count as mbv_cove8_23_, oasistesta0_.normative_source_id as normati16_23_, oasistesta0_.other_tag_on_assertion as other_ta9_23_, oasistesta0_.page_number as page_nu10_23_, oasistesta0_.predicate_id as predica17_23_, oasistesta0_.prerequisite_id as prerequ18_23_, oasistesta0_.prescription_id as prescri19_23_, oasistesta0_.status as status11_23_, oasistesta0_.target_id as target_20_23_, oasistesta0_.testable as testabl12_23_, oasistesta0_.tests_coverage_count as tests_c13_23_, oasistesta0_.tf_rules_coverage_count as tf_rule14_23_ from am_oasis_test_assertion oasistesta0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2
12:54:05,617 DEBUG [main] StandardQueryCache:212 - Checking query spaces are up-to-date: [am_oasis_test_assertion]
12:54:05,617 DEBUG [main] EhcacheGeneralDataRegion:69 - key: am_oasis_test_assertion
12:54:05,617 DEBUG [main] UpdateTimestampsCache:175 - [am_oasis_test_assertion] last update timestamp: 6373798893932544, result set timestamp: 6373798893547520
12:54:05,617 DEBUG [main] StandardQueryCache:151 - Cached query results were not up-to-date
12:54:05,618 DEBUG [main] SQL:104 - 
    select
        distinct oasistesta0_.id as id1_23_,
        oasistesta0_.last_changed as last_cha2_23_,
        oasistesta0_.last_modifier_id as last_mod3_23_,
        oasistesta0_.applies_to_count as applies_4_23_,
        oasistesta0_.assertion_id as assertio5_23_,
        oasistesta0_.comment as comment6_23_,
        oasistesta0_.coverage_count as coverage7_23_,
        oasistesta0_.description_id as descrip15_23_,
        oasistesta0_.mbv_coverage_count as mbv_cove8_23_,
        oasistesta0_.normative_source_id as normati16_23_,
        oasistesta0_.other_tag_on_assertion as other_ta9_23_,
        oasistesta0_.page_number as page_nu10_23_,
        oasistesta0_.predicate_id as predica17_23_,
        oasistesta0_.prerequisite_id as prerequ18_23_,
        oasistesta0_.prescription_id as prescri19_23_,
        oasistesta0_.status as status11_23_,
        oasistesta0_.target_id as target_20_23_,
        oasistesta0_.testable as testabl12_23_,
        oasistesta0_.tests_coverage_count as tests_c13_23_,
        oasistesta0_.tf_rules_coverage_count as tf_rule14_23_ 
    from
        am_oasis_test_assertion oasistesta0_
12:54:05,618 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,618 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,618 DEBUG [main] Loader:948 - Result set row: 0
12:54:05,619 DEBUG [main] Loader:1480 - Result row: EntityKey[net.ihe.gazelle.oasis.testassertion.OasisTestAssertion#23]
12:54:05,619 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,619 DEBUG [main] StandardQueryCache:104 - Caching query results in region: org.hibernate.cache.internal.StandardQueryCache; timestamp=6373798894055424
12:54:05,619 DEBUG [main] EhcacheGeneralDataRegion:100 - key: sql: select distinct oasistesta0_.id as id1_23_, oasistesta0_.last_changed as last_cha2_23_, oasistesta0_.last_modifier_id as last_mod3_23_, oasistesta0_.applies_to_count as applies_4_23_, oasistesta0_.assertion_id as assertio5_23_, oasistesta0_.comment as comment6_23_, oasistesta0_.coverage_count as coverage7_23_, oasistesta0_.description_id as descrip15_23_, oasistesta0_.mbv_coverage_count as mbv_cove8_23_, oasistesta0_.normative_source_id as normati16_23_, oasistesta0_.other_tag_on_assertion as other_ta9_23_, oasistesta0_.page_number as page_nu10_23_, oasistesta0_.predicate_id as predica17_23_, oasistesta0_.prerequisite_id as prerequ18_23_, oasistesta0_.prescription_id as prescri19_23_, oasistesta0_.status as status11_23_, oasistesta0_.target_id as target_20_23_, oasistesta0_.testable as testabl12_23_, oasistesta0_.tests_coverage_count as tests_c13_23_, oasistesta0_.tf_rules_coverage_count as tf_rule14_23_ from am_oasis_test_assertion oasistesta0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2 value: [6373798894055424, 23]
12:54:05,619 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,620 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,620 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,620 DEBUG [main] AbstractTransactionImpl:158 - begin
12:54:05,620 DEBUG [org%002ehibernate%002ecache%002einternal%002e%0053tandard%0051uery%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,620 DEBUG [main] JdbcTransaction:69 - initial autocommit status: true
12:54:05,621 DEBUG [main] JdbcTransaction:71 - disabling autocommit
12:54:05,621 DEBUG [org%002ehibernate%002ecache%002einternal%002e%0053tandard%0051uery%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,621 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,621 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,621 DEBUG [main] Collections:76 - Collection dereferenced: [net.ihe.gazelle.oasis.testassertion.OasisTestAssertion.tags#23]
12:54:05,622 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 0 insertions, 0 updates, 2 deletions to 5 objects
12:54:05,622 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 0 (re)creations, 0 updates, 1 removals to 1 collections
12:54:05,622 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,622 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisPredicate{language=0, id=23, content=predicate content}
12:54:05,622 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTarget{idScheme=testing 23, lastChanged=2019-04-24 12:54:05.546190049, testAssertions=null, lastModifierId=null, language=null, id=23, type=null, content=null}
12:54:05,622 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisNormativeSource{derivedSourceItems=null, interpretation=null, textSourceItems=null, lastChanged=2019-04-24 12:54:05.554121876, refSourceItems=null, testAssertions=null, lastModifierId=null, comment=null, id=23, content=null}
12:54:05,622 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTestAssertion{mbv=null, normativeSource=net.ihe.gazelle.oasis.testassertion.OasisNormativeSource#23, pageNumber=null, coverageCount=null, testable=true, description=null, otherTagOnAssertion=null, testSteps=null, predicate=net.ihe.gazelle.oasis.testassertion.OasisPredicate#23, assertionId=Assertion-id23, tfRulesCoverageCount=null, appliesToCount=null, lastModifierId=null, id=23, tfTransactions=null, tfIntegrationProfiles=null, variables=null, lastChanged=2019-04-24 12:54:05.561826955, prerequisite=null, tfActors=null, tfAIPOs=null, tags=[], target=net.ihe.gazelle.oasis.testassertion.OasisTarget#23, mbvCoverageCount=null, tests=null, tfAuditMessages=null, prescription=null, testsCoverageCount=null, tfStandards=null, comment=null, scopes=null, tfRules=null, status=null}
12:54:05,622 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,623 DEBUG [main] UpdateTimestampsCache:88 - Pre-invalidating space [am_oasis_test_assertion_tag], timestamp: 6373799139831808
12:54:05,623 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_test_assertion_tag value: 6373799139831808
12:54:05,623 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,623 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,623 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,624 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,624 DEBUG [main] SQL:104 - 
    delete 
    from
        am_oasis_test_assertion 
    where
        id=?
12:54:05,624 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,624 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,624 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,625 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,625 DEBUG [main] UpdateTimestampsCache:88 - Pre-invalidating space [am_oasis_test_assertion], timestamp: 6373799139840000
12:54:05,625 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_test_assertion value: 6373799139840000
12:54:05,626 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,626 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,626 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,626 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,626 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,626 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,627 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,627 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,627 DEBUG [main] SQL:104 - 
    delete 
    from
        am_oasis_predicate 
    where
        id=?
12:54:05,627 DEBUG [instances.data] Segment:779 - fault removed 0 from heap
12:54:05,628 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,628 DEBUG [instances.data] Segment:796 - fault added 0 on disk
12:54:05,628 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,628 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,628 DEBUG [main] UpdateTimestampsCache:88 - Pre-invalidating space [am_oasis_predicate], timestamp: 6373799139852288
12:54:05,629 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_predicate value: 6373799139852288
12:54:05,629 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,629 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,629 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,629 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,629 DEBUG [main] AbstractTransactionImpl:173 - committing
12:54:05,629 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,629 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,629 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,630 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 0 insertions, 0 updates, 0 deletions to 3 objects
12:54:05,630 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
12:54:05,630 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,630 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTarget{idScheme=testing 23, lastChanged=2019-04-24 12:54:05.546190049, testAssertions=null, lastModifierId=null, language=null, id=23, type=null, content=null}
12:54:05,630 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisNormativeSource{derivedSourceItems=null, interpretation=null, textSourceItems=null, lastChanged=2019-04-24 12:54:05.554121876, refSourceItems=null, testAssertions=null, lastModifierId=null, comment=null, id=23, content=null}
12:54:05,630 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,631 DEBUG [main] JdbcTransaction:113 - committed JDBC Connection
12:54:05,631 DEBUG [main] JdbcTransaction:126 - re-enabling autocommit
12:54:05,631 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,631 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,631 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,632 DEBUG [main] UpdateTimestampsCache:125 - Invalidating space [am_oasis_predicate], timestamp: 6373798894108672
12:54:05,632 DEBUG [instances.data] Segment:779 - fault removed 0 from heap
12:54:05,632 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_predicate value: 6373798894108672
12:54:05,632 DEBUG [instances.data] Segment:796 - fault added 0 on disk
12:54:05,632 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,632 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,632 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,633 DEBUG [main] UpdateTimestampsCache:125 - Invalidating space [am_oasis_test_assertion], timestamp: 6373798894108672
12:54:05,633 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,633 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_test_assertion value: 6373798894108672
12:54:05,633 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,633 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,633 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,633 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,633 DEBUG [main] UpdateTimestampsCache:125 - Invalidating space [am_oasis_test_assertion_tag], timestamp: 6373798894108672
12:54:05,633 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,634 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_test_assertion_tag value: 6373798894108672
12:54:05,634 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,634 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,634 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,634 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,634 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,634 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,635 DEBUG [main] StandardQueryCache:138 - Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache
12:54:05,635 DEBUG [main] EhcacheGeneralDataRegion:69 - key: sql: select distinct oasispredi0_.id as id1_17_, oasispredi0_.content as content2_17_, oasispredi0_.language as language3_17_ from am_oasis_predicate oasispredi0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2
12:54:05,635 DEBUG [main] StandardQueryCache:212 - Checking query spaces are up-to-date: [am_oasis_predicate]
12:54:05,635 DEBUG [main] EhcacheGeneralDataRegion:69 - key: am_oasis_predicate
12:54:05,635 DEBUG [main] UpdateTimestampsCache:175 - [am_oasis_predicate] last update timestamp: 6373798894108672, result set timestamp: 6373798893608960
12:54:05,635 DEBUG [main] StandardQueryCache:151 - Cached query results were not up-to-date
12:54:05,635 DEBUG [main] SQL:104 - 
    select
        distinct oasispredi0_.id as id1_17_,
        oasispredi0_.content as content2_17_,
        oasispredi0_.language as language3_17_ 
    from
        am_oasis_predicate oasispredi0_
12:54:05,636 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,636 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,636 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,636 DEBUG [main] StandardQueryCache:104 - Caching query results in region: org.hibernate.cache.internal.StandardQueryCache; timestamp=6373798894125056
12:54:05,636 DEBUG [main] EhcacheGeneralDataRegion:100 - key: sql: select distinct oasispredi0_.id as id1_17_, oasispredi0_.content as content2_17_, oasispredi0_.language as language3_17_ from am_oasis_predicate oasispredi0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2 value: [6373798894125056]
12:54:05,636 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,637 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,637 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,637 DEBUG [org%002ehibernate%002ecache%002einternal%002e%0053tandard%0051uery%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,637 DEBUG [org%002ehibernate%002ecache%002einternal%002e%0053tandard%0051uery%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,637 DEBUG [main] StandardQueryCache:138 - Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache
12:54:05,638 DEBUG [main] EhcacheGeneralDataRegion:69 - key: sql: select distinct oasistarge0_.id as id1_22_, oasistarge0_.last_changed as last_cha2_22_, oasistarge0_.last_modifier_id as last_mod3_22_, oasistarge0_.content as content4_22_, oasistarge0_.idScheme as idScheme5_22_, oasistarge0_.language as language6_22_, oasistarge0_.type as type7_22_ from am_oasis_target oasistarge0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2
12:54:05,638 DEBUG [main] StandardQueryCache:212 - Checking query spaces are up-to-date: [am_oasis_target]
12:54:05,638 DEBUG [main] EhcacheGeneralDataRegion:69 - key: am_oasis_target
12:54:05,638 DEBUG [main] UpdateTimestampsCache:175 - [am_oasis_target] last update timestamp: 6373798893785089, result set timestamp: 6373798893617152
12:54:05,638 DEBUG [main] StandardQueryCache:151 - Cached query results were not up-to-date
12:54:05,638 DEBUG [main] SQL:104 - 
    select
        distinct oasistarge0_.id as id1_22_,
        oasistarge0_.last_changed as last_cha2_22_,
        oasistarge0_.last_modifier_id as last_mod3_22_,
        oasistarge0_.content as content4_22_,
        oasistarge0_.idScheme as idScheme5_22_,
        oasistarge0_.language as language6_22_,
        oasistarge0_.type as type7_22_ 
    from
        am_oasis_target oasistarge0_
12:54:05,638 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,638 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,639 DEBUG [main] Loader:948 - Result set row: 0
12:54:05,639 DEBUG [main] Loader:1480 - Result row: EntityKey[net.ihe.gazelle.oasis.testassertion.OasisTarget#23]
12:54:05,639 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,639 DEBUG [main] StandardQueryCache:104 - Caching query results in region: org.hibernate.cache.internal.StandardQueryCache; timestamp=6373798894137344
12:54:05,639 DEBUG [main] EhcacheGeneralDataRegion:100 - key: sql: select distinct oasistarge0_.id as id1_22_, oasistarge0_.last_changed as last_cha2_22_, oasistarge0_.last_modifier_id as last_mod3_22_, oasistarge0_.content as content4_22_, oasistarge0_.idScheme as idScheme5_22_, oasistarge0_.language as language6_22_, oasistarge0_.type as type7_22_ from am_oasis_target oasistarge0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2 value: [6373798894137344, 23]
12:54:05,639 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,640 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,640 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,640 DEBUG [main] AbstractTransactionImpl:158 - begin
12:54:05,640 DEBUG [org%002ehibernate%002ecache%002einternal%002e%0053tandard%0051uery%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,640 DEBUG [main] JdbcTransaction:69 - initial autocommit status: true
12:54:05,640 DEBUG [main] JdbcTransaction:71 - disabling autocommit
12:54:05,640 DEBUG [org%002ehibernate%002ecache%002einternal%002e%0053tandard%0051uery%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,640 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,641 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,641 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 0 insertions, 0 updates, 1 deletions to 3 objects
12:54:05,641 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
12:54:05,641 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,641 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisTarget{idScheme=testing 23, lastChanged=2019-04-24 12:54:05.546190049, testAssertions=null, lastModifierId=null, language=null, id=23, type=null, content=null}
12:54:05,641 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisNormativeSource{derivedSourceItems=null, interpretation=null, textSourceItems=null, lastChanged=2019-04-24 12:54:05.554121876, refSourceItems=null, testAssertions=null, lastModifierId=null, comment=null, id=23, content=null}
12:54:05,641 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,641 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,642 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,642 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,642 DEBUG [main] SQL:104 - 
    delete 
    from
        am_oasis_target 
    where
        id=?
12:54:05,642 DEBUG [instances.data] Segment:779 - fault removed 0 from heap
12:54:05,642 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,642 DEBUG [instances.data] Segment:796 - fault added 0 on disk
12:54:05,642 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,643 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,643 DEBUG [main] UpdateTimestampsCache:88 - Pre-invalidating space [am_oasis_target], timestamp: 6373799139913728
12:54:05,643 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_target value: 6373799139913728
12:54:05,643 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,644 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,644 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,644 DEBUG [main] AbstractTransactionImpl:173 - committing
12:54:05,644 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,644 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,644 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,644 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,644 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 0 insertions, 0 updates, 0 deletions to 2 objects
12:54:05,645 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
12:54:05,645 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,645 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisNormativeSource{derivedSourceItems=null, interpretation=null, textSourceItems=null, lastChanged=2019-04-24 12:54:05.554121876, refSourceItems=null, testAssertions=null, lastModifierId=null, comment=null, id=23, content=null}
12:54:05,645 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,646 DEBUG [main] JdbcTransaction:113 - committed JDBC Connection
12:54:05,646 DEBUG [main] JdbcTransaction:126 - re-enabling autocommit
12:54:05,646 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,646 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,646 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,646 DEBUG [main] UpdateTimestampsCache:125 - Invalidating space [am_oasis_target], timestamp: 6373798894166017
12:54:05,647 DEBUG [instances.data] Segment:779 - fault removed 0 from heap
12:54:05,647 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_target value: 6373798894166017
12:54:05,647 DEBUG [instances.data] Segment:796 - fault added 0 on disk
12:54:05,647 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,647 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,647 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,647 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,647 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,647 DEBUG [main] StandardQueryCache:138 - Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache
12:54:05,648 DEBUG [main] EhcacheGeneralDataRegion:69 - key: sql: select distinct oasisnorma0_.id as id1_13_, oasisnorma0_.last_changed as last_cha2_13_, oasisnorma0_.last_modifier_id as last_mod3_13_, oasisnorma0_.comment_id as comment_5_13_, oasisnorma0_.content as content4_13_, oasisnorma0_.interpretation_id as interpre6_13_ from am_oasis_normative_source oasisnorma0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2
12:54:05,648 DEBUG [main] StandardQueryCache:212 - Checking query spaces are up-to-date: [am_oasis_normative_source]
12:54:05,648 DEBUG [main] EhcacheGeneralDataRegion:69 - key: am_oasis_normative_source
12:54:05,648 DEBUG [main] UpdateTimestampsCache:175 - [am_oasis_normative_source] last update timestamp: 6373798893817856, result set timestamp: 6373798893654016
12:54:05,648 DEBUG [main] StandardQueryCache:151 - Cached query results were not up-to-date
12:54:05,648 DEBUG [main] SQL:104 - 
    select
        distinct oasisnorma0_.id as id1_13_,
        oasisnorma0_.last_changed as last_cha2_13_,
        oasisnorma0_.last_modifier_id as last_mod3_13_,
        oasisnorma0_.comment_id as comment_5_13_,
        oasisnorma0_.content as content4_13_,
        oasisnorma0_.interpretation_id as interpre6_13_ 
    from
        am_oasis_normative_source oasisnorma0_
12:54:05,648 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,649 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,649 DEBUG [main] Loader:948 - Result set row: 0
12:54:05,649 DEBUG [main] Loader:1480 - Result row: EntityKey[net.ihe.gazelle.oasis.testassertion.OasisNormativeSource#23]
12:54:05,649 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,649 DEBUG [main] StandardQueryCache:104 - Caching query results in region: org.hibernate.cache.internal.StandardQueryCache; timestamp=6373798894178304
12:54:05,650 DEBUG [main] EhcacheGeneralDataRegion:100 - key: sql: select distinct oasisnorma0_.id as id1_13_, oasisnorma0_.last_changed as last_cha2_13_, oasisnorma0_.last_modifier_id as last_mod3_13_, oasisnorma0_.comment_id as comment_5_13_, oasisnorma0_.content as content4_13_, oasisnorma0_.interpretation_id as interpre6_13_ from am_oasis_normative_source oasisnorma0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2 value: [6373798894178304, 23]
12:54:05,650 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,650 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,650 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,650 DEBUG [main] AbstractTransactionImpl:158 - begin
12:54:05,651 DEBUG [org%002ehibernate%002ecache%002einternal%002e%0053tandard%0051uery%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,651 DEBUG [main] JdbcTransaction:69 - initial autocommit status: true
12:54:05,651 DEBUG [main] JdbcTransaction:71 - disabling autocommit
12:54:05,651 DEBUG [org%002ehibernate%002ecache%002einternal%002e%0053tandard%0051uery%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,651 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,651 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,651 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 0 insertions, 0 updates, 1 deletions to 2 objects
12:54:05,651 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
12:54:05,651 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,652 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.OasisNormativeSource{derivedSourceItems=null, interpretation=null, textSourceItems=null, lastChanged=2019-04-24 12:54:05.554121876, refSourceItems=null, testAssertions=null, lastModifierId=null, comment=null, id=23, content=null}
12:54:05,652 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,652 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,652 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,652 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,653 DEBUG [main] SQL:104 - 
    delete 
    from
        am_oasis_normative_source 
    where
        id=?
12:54:05,653 DEBUG [instances.data] Segment:779 - fault removed 0 from heap
12:54:05,653 DEBUG [instances.data] Segment:796 - fault added 0 on disk
12:54:05,653 DEBUG [main] GooGooStatementCache:179 - com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT
12:54:05,653 DEBUG [main] GooGooStatementCache:196 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 1; num connections: 1; num keys: 45
12:54:05,653 DEBUG [main] GooGooStatementCache:271 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 45; checked out: 0; num connections: 1; num keys: 45
12:54:05,654 DEBUG [main] UpdateTimestampsCache:88 - Pre-invalidating space [am_oasis_normative_source], timestamp: 6373799139958784
12:54:05,654 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_normative_source value: 6373799139958784
12:54:05,654 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,654 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,654 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,654 DEBUG [main] AbstractTransactionImpl:173 - committing
12:54:05,654 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,654 DEBUG [main] AbstractFlushingEventListener:147 - Processing flush-time cascades
12:54:05,654 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,655 DEBUG [main] AbstractFlushingEventListener:188 - Dirty checking collections
12:54:05,655 DEBUG [main] AbstractFlushingEventListener:121 - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
12:54:05,655 DEBUG [main] AbstractFlushingEventListener:128 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
12:54:05,655 DEBUG [main] EntityPrinter:114 - Listing entities:
12:54:05,655 DEBUG [main] EntityPrinter:121 - net.ihe.gazelle.oasis.testassertion.MbvCoverageStatus{idScheme=idScheme, assertionId=assert-id, mbvService=net.ihe.gazelle.oasis.testassertion.MbvService#1, id=1, coverageStatus=0}
12:54:05,655 DEBUG [main] JdbcTransaction:113 - committed JDBC Connection
12:54:05,656 DEBUG [main] JdbcTransaction:126 - re-enabling autocommit
12:54:05,656 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,656 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,656 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,656 DEBUG [main] UpdateTimestampsCache:125 - Invalidating space [am_oasis_normative_source], timestamp: 6373798894206977
12:54:05,656 DEBUG [instances.data] Segment:779 - fault removed 0 from heap
12:54:05,656 DEBUG [main] EhcacheGeneralDataRegion:100 - key: am_oasis_normative_source value: 6373798894206977
12:54:05,656 DEBUG [instances.data] Segment:796 - fault added 0 on disk
12:54:05,657 DEBUG [main] Segment:425 - put added 0 on heap
12:54:05,657 DEBUG [main] Segment:453 - put updated, deleted 0 on heap
12:54:05,657 DEBUG [main] Segment:457 - put updated, deleted 0 on disk
12:54:05,657 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:779 - fault removed 0 from heap
12:54:05,657 DEBUG [org%002ehibernate%002ecache%002espi%002e%0055pdate%0054imestamps%0043ache.data] Segment:796 - fault added 0 on disk
12:54:05,657 DEBUG [main] StandardQueryCache:138 - Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache
12:54:05,657 DEBUG [main] EhcacheGeneralDataRegion:69 - key: sql: select distinct oasisdescr0_.id as id1_11_, oasisdescr0_.last_changed as last_cha2_11_, oasisdescr0_.last_modifier_id as last_mod3_11_, oasisdescr0_.content as content4_11_ from am_oasis_description oasisdescr0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2
12:54:05,657 DEBUG [main] StandardQueryCache:212 - Checking query spaces are up-to-date: [am_oasis_description]
12:54:05,658 DEBUG [main] EhcacheGeneralDataRegion:69 - key: am_oasis_description
12:54:05,658 DEBUG [main] EhcacheGeneralDataRegion:76 - Element for key am_oasis_description is null
12:54:05,658 DEBUG [main] StandardQueryCache:156 - Returning cached query results
12:54:05,658 DEBUG [main] StandardQueryCache:138 - Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache
12:54:05,658 DEBUG [main] EhcacheGeneralDataRegion:69 - key: sql: select distinct oasistag0_.id as id1_21_, oasistag0_.content as content2_21_, oasistag0_.name as name3_21_ from am_oasis_tag oasistag0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2
12:54:05,658 DEBUG [main] StandardQueryCache:212 - Checking query spaces are up-to-date: [am_oasis_tag]
12:54:05,658 DEBUG [main] EhcacheGeneralDataRegion:69 - key: am_oasis_tag
12:54:05,658 DEBUG [main] EhcacheGeneralDataRegion:76 - Element for key am_oasis_tag is null
12:54:05,659 DEBUG [main] StandardQueryCache:156 - Returning cached query results
12:54:05,659 DEBUG [main] StandardQueryCache:138 - Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache
12:54:05,659 DEBUG [main] EhcacheGeneralDataRegion:69 - key: sql: select distinct oasisvaria0_.id as id1_27_, oasisvaria0_.last_changed as last_cha2_27_, oasisvaria0_.last_modifier_id as last_mod3_27_, oasisvaria0_.content as content4_27_, oasisvaria0_.language as language5_27_, oasisvaria0_.name as name6_27_ from am_oasis_variable oasisvaria0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2
12:54:05,659 DEBUG [main] StandardQueryCache:212 - Checking query spaces are up-to-date: [am_oasis_variable]
12:54:05,659 DEBUG [main] EhcacheGeneralDataRegion:69 - key: am_oasis_variable
12:54:05,659 DEBUG [main] EhcacheGeneralDataRegion:76 - Element for key am_oasis_variable is null
12:54:05,659 DEBUG [main] StandardQueryCache:156 - Returning cached query results
12:54:05,660 DEBUG [main] StandardQueryCache:138 - Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache
12:54:05,660 DEBUG [main] EhcacheGeneralDataRegion:69 - key: sql: select distinct oasisprere0_.id as id1_18_, oasisprere0_.last_changed as last_cha2_18_, oasisprere0_.last_modifier_id as last_mod3_18_, oasisprere0_.content as content4_18_, oasisprere0_.language as language5_18_ from am_oasis_prerequisite oasisprere0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2
12:54:05,660 DEBUG [main] StandardQueryCache:212 - Checking query spaces are up-to-date: [am_oasis_prerequisite]
12:54:05,660 DEBUG [main] EhcacheGeneralDataRegion:69 - key: am_oasis_prerequisite
12:54:05,660 DEBUG [main] EhcacheGeneralDataRegion:76 - Element for key am_oasis_prerequisite is null
12:54:05,660 DEBUG [main] StandardQueryCache:156 - Returning cached query results
12:54:05,660 DEBUG [main] StandardQueryCache:138 - Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache
12:54:05,660 DEBUG [main] EhcacheGeneralDataRegion:69 - key: sql: select distinct oasisrefso0_.id as id1_20_, oasisrefso0_.last_changed as last_cha2_20_, oasisrefso0_.last_modifier_id as last_mod3_20_, oasisrefso0_.document_id as document4_20_, oasisrefso0_.name as name5_20_, oasisrefso0_.resource_provenance_id as resource6_20_, oasisrefso0_.revision_id as revision7_20_, oasisrefso0_.uri as uri8_20_, oasisrefso0_.version_id as version_9_20_ from am_oasis_ref_source_item oasisrefso0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2
12:54:05,661 DEBUG [main] StandardQueryCache:212 - Checking query spaces are up-to-date: [am_oasis_ref_source_item]
12:54:05,661 DEBUG [main] EhcacheGeneralDataRegion:69 - key: am_oasis_ref_source_item
12:54:05,661 DEBUG [main] EhcacheGeneralDataRegion:76 - Element for key am_oasis_ref_source_item is null
12:54:05,661 DEBUG [main] StandardQueryCache:156 - Returning cached query results
12:54:05,661 DEBUG [main] AbstractTestQueryJunit4:78 - Shuting down Hibernate JPA layer.
[INFO] Tests run: 5, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.863 s - in net.ihe.gazelle.AssertionManager.assertion.link.coverage.TestLinkRefresherTest
[INFO] 
[INFO] Results:
[INFO] 
[WARNING] Tests run: 21, Failures: 0, Errors: 0, Skipped: 1
[INFO] 
[JENKINS] Recording test results
[INFO] 
[INFO] --- jacoco-maven-plugin:0.7.9:report (post-unit-test) @ AssertionManagerGui-ejb ---
[INFO] Skipping JaCoCo execution due to missing execution data file.
[INFO] 
[INFO] --- jacoco-maven-plugin:0.7.9:report (default-report) @ AssertionManagerGui-ejb ---
[INFO] Skipping JaCoCo execution due to missing execution data file.
[INFO] 
[INFO] --- maven-ejb-plugin:2.3:ejb (default-ejb) @ AssertionManagerGui-ejb ---
[INFO] Building EJB AssertionManagerGui-ejb with EJB version 3.0
[INFO] Building jar: /home/jenkins/.hudson/jobs/AssertionManager-Gui-SNAPSHOT/workspace/AssertionManagerGui-ejb/target/AssertionManagerGui-ejb.jar
[INFO] 
[INFO] --- maven-source-plugin:3.0.1:jar-no-fork (attach-sources) @ AssertionManagerGui-ejb ---
[INFO] Building jar: /home/jenkins/.hudson/jobs/AssertionManager-Gui-SNAPSHOT/workspace/AssertionManagerGui-ejb/target/AssertionManagerGui-ejb-sources.jar
[INFO] 
[INFO] --- maven-jar-plugin:2.6:test-jar (default) @ AssertionManagerGui-ejb ---
[INFO] Building jar: /home/jenkins/.hudson/jobs/AssertionManager-Gui-SNAPSHOT/workspace/AssertionManagerGui-ejb/target/AssertionManagerGui-ejb-tests.jar
[INFO] 
[INFO] --- maven-install-plugin:2.4:install (default-install) @ AssertionManagerGui-ejb ---
[INFO] Installing /home/jenkins/.hudson/jobs/AssertionManager-Gui-SNAPSHOT/workspace/AssertionManagerGui-ejb/target/AssertionManagerGui-ejb.jar to /home/jenkins/.m2/repository/net/ihe/gazelle/AssertionManagerGui-ejb/4.1.1-SNAPSHOT/AssertionManagerGui-ejb-4.1.1-SNAPSHOT.jar
[INFO] Installing /home/jenkins/.hudson/jobs/AssertionManager-Gui-SNAPSHOT/workspace/AssertionManagerGui-ejb/pom.xml to /home/jenkins/.m2/repository/net/ihe/gazelle/AssertionManagerGui-ejb/4.1.1-SNAPSHOT/AssertionManagerGui-ejb-4.1.1-SNAPSHOT.pom
[INFO] Installing /home/jenkins/.hudson/jobs/AssertionManager-Gui-SNAPSHOT/workspace/AssertionManagerGui-ejb/target/AssertionManagerGui-ejb-sources.jar to /home/jenkins/.m2/repository/net/ihe/gazelle/AssertionManagerGui-ejb/4.1.1-SNAPSHOT/AssertionManagerGui-ejb-4.1.1-SNAPSHOT-sources.jar
[INFO] Installing /home/jenkins/.hudson/jobs/AssertionManager-Gui-SNAPSHOT/workspace/AssertionManagerGui-ejb/target/AssertionManagerGui-ejb-tests.jar to /home/jenkins/.m2/repository/net/ihe/gazelle/AssertionManagerGui-ejb/4.1.1-SNAPSHOT/AssertionManagerGui-ejb-4.1.1-SNAPSHOT-tests.jar