search

WrenSecurity / wrensec-commons

Community fork of ForgeRock Commons, which contains common utility code used by multiple products originally developed by ForgeRock.
http://wrensecurity.org
0 stars 10 forks source link

Commons 20.0.0+ has test failures in `forgerock-audit-handler-csv` #6

Closed Kortanul closed 5 years ago

Kortanul commented 6 years ago

Affected Versions

Build Environment

Steps to Reproduce

  1. Check out wrensec-commons on a sustaining/ branch for any of the following versions:
    • 20.0.0
    • 20.0.1
    • 20.1.0
    • 20.1.1
    • 21.0.0-alpha-6
    • 21.0.1-alpha-6
  2. Attempt to run tests with mvn clean test -Dignore-artifact-sigs -rf :forgerock-audit-handler-csv.

Expected Results

Actual Results

The project compiles successfully but fails with the following test failures:

Tests run: 29, Failures: 2, Errors: 0, Skipped: 0, Time elapsed: 42.698 sec <<< FAILURE! - in TestSuite
shouldGenerateHMACColumn(org.forgerock.audit.handlers.csv.SecureCsvWriterTest)  Time elapsed: 2.776 sec  <<< FAILURE!
java.lang.AssertionError:
Expecting:
 <"FOO,HMAC,SIGNATURE
bar,uLkBIiPY0+yyseXNACJX5SBwqV4RDSN8Ab8Jz7c3cYI=,
quix,taHEQat9MgErQvhG1iRGSJQPfe1SzIemjSyBtB5+hfU=,
,,g0dSW8i7orW7Mb4voYoAGI+v1Lqp0zsEZGBZ6CWSpcjeswHGgXho9HggqTQgT3nnezj/hl6djnePg2LrIBCCkDGpuWAIXerMpyJO0eySSWi8cdNckyMnZZNU3YgaTmmg16mcwn1CQ9O8XO4a9suAovvAmq+6iVMgjK05wKAZORLq01MqIPCxsH9xaoUgBIVDXJcmgu5UlYAYPjcc4tgcAFx9Sph3M697VyI2iyZuD5fvsho7kJZTAqVF4ijRlQ0WHQGWJXKLcQ6OJeBARRPSP9KXODTRMmtJHCMcz6eTclAR5zkGxso+nDXO3dlzwSruEoZxNcV4llAzLH7gvgbfiQ==
,,bLIchgcK6Uxh+i6hYn69/ottxP9zrxoBraX3Dsl3NcfVZM16bdqu0UYWjG1ekzYLvTYEOppjwDi5o2zhpgC/+D0fYSsJnBVZvSHw+u8Z/XaQTWturJNIvSrJjKSaNZcB+yqKRobBiK6XiF7G49yQSRdkk2KvxY3xoLvI1ZaD2X+K8jlCWzdLZDGhaTsAvMXSw0RyP79CZ44efuyiurc3HAK+M1oUMjZCXOjxLy2J32EQcqsBXUiDifkVJQgeZ258JUls0/RvjvLo0u0za/SguxJRqUeKfh0vs/OXPA/7g+/eGyQk6ur3HmqHhuyO7OyYdZj5SW30R6zGevlRMGglyA==
">
to be equal to:
 <"FOO,HMAC,SIGNATURE
bar,uLkBIiPY0+yyseXNACJX5SBwqV4RDSN8Ab8Jz7c3cYI=,
quix,taHEQat9MgErQvhG1iRGSJQPfe1SzIemjSyBtB5+hfU=,
,,g0dSW8i7orW7Mb4voYoAGI+v1Lqp0zsEZGBZ6CWSpcjeswHGgXho9HggqTQgT3nnezj/hl6djnePg2LrIBCCkDGpuWAIXerMpyJO0eySSWi8cdNckyMnZZNU3YgaTmmg16mcwn1CQ9O8XO4a9suAovvAmq+6iVMgjK05wKAZORLq01MqIPCxsH9xaoUgBIVDXJcmgu5UlYAYPjcc4tgcAFx9Sph3M697VyI2iyZuD5fvsho7kJZTAqVF4ijRlQ0WHQGWJXKLcQ6OJeBARRPSP9KXODTRMmtJHCMcz6eTclAR5zkGxso+nDXO3dlzwSruEoZxNcV4llAzLH7gvgbfiQ==
">
but was not.
        at org.forgerock.audit.handlers.csv.SecureCsvWriterTest.shouldGenerateHMACColumn(SecureCsvWriterTest.java:166)

shouldRotateCsvAndKeyStoreFile(org.forgerock.audit.handlers.csv.SecureCsvWriterTest)  Time elapsed: 16.955 sec  <<< FAILURE!
java.lang.AssertionError:
Expected size:<6> but was:<8> in:
<[/tmp/SecureCsvWriterTest1681760462361108705/tamper-evident-shouldRotateCsvAndKeyStoreFile.csv-2018.10.21-21.58.20.601,
    /tmp/SecureCsvWriterTest1681760462361108705/tamper-evident-shouldRotateCsvAndKeyStoreFile.csv-2018.10.21-21.58.22.854,
    /tmp/SecureCsvWriterTest1681760462361108705/tamper-evident-shouldRotateCsvAndKeyStoreFile.csv-2018.10.21-21.58.25.709,
    /tmp/SecureCsvWriterTest1681760462361108705/tamper-evident-shouldRotateCsvAndKeyStoreFile.csv-2018.10.21-21.58.28.555,
    /tmp/SecureCsvWriterTest1681760462361108705/tamper-evident-shouldRotateCsvAndKeyStoreFile.csv-2018.10.21-21.58.30.956,
    /tmp/SecureCsvWriterTest1681760462361108705/tamper-evident-shouldRotateCsvAndKeyStoreFile.csv-2018.10.21-21.58.32.947,
    /tmp/SecureCsvWriterTest1681760462361108705/tamper-evident-shouldRotateCsvAndKeyStoreFile.csv-2018.10.21-21.58.34.595,
    /tmp/SecureCsvWriterTest1681760462361108705/tamper-evident-shouldRotateCsvAndKeyStoreFile.csv-2018.10.21-21.58.35.562]>
        at org.forgerock.audit.handlers.csv.SecureCsvWriterTest.shouldRotateCsvAndKeyStoreFile(SecureCsvWriterTest.java:257)

Results :

Failed tests:
  SecureCsvWriterTest.shouldGenerateHMACColumn:166
Expecting:
 <"FOO,HMAC,SIGNATURE
bar,uLkBIiPY0+yyseXNACJX5SBwqV4RDSN8Ab8Jz7c3cYI=,
quix,taHEQat9MgErQvhG1iRGSJQPfe1SzIemjSyBtB5+hfU=,
,,g0dSW8i7orW7Mb4voYoAGI+v1Lqp0zsEZGBZ6CWSpcjeswHGgXho9HggqTQgT3nnezj/hl6djnePg2LrIBCCkDGpuWAIXerMpyJO0eySSWi8cdNckyMnZZNU3YgaTmmg16mcwn1CQ9O8XO4a9suAovvAmq+6iVMgjK05wKAZORLq01MqIPCxsH9xaoUgBIVDXJcmgu5UlYAYPjcc4tgcAFx9Sph3M697VyI2iyZuD5fvsho7kJZTAqVF4ijRlQ0WHQGWJXKLcQ6OJeBARRPSP9KXODTRMmtJHCMcz6eTclAR5zkGxso+nDXO3dlzwSruEoZxNcV4llAzLH7gvgbfiQ==
,,bLIchgcK6Uxh+i6hYn69/ottxP9zrxoBraX3Dsl3NcfVZM16bdqu0UYWjG1ekzYLvTYEOppjwDi5o2zhpgC/+D0fYSsJnBVZvSHw+u8Z/XaQTWturJNIvSrJjKSaNZcB+yqKRobBiK6XiF7G49yQSRdkk2KvxY3xoLvI1ZaD2X+K8jlCWzdLZDGhaTsAvMXSw0RyP79CZ44efuyiurc3HAK+M1oUMjZCXOjxLy2J32EQcqsBXUiDifkVJQgeZ258JUls0/RvjvLo0u0za/SguxJRqUeKfh0vs/OXPA/7g+/eGyQk6ur3HmqHhuyO7OyYdZj5SW30R6zGevlRMGglyA==
">
to be equal to:
 <"FOO,HMAC,SIGNATURE
bar,uLkBIiPY0+yyseXNACJX5SBwqV4RDSN8Ab8Jz7c3cYI=,
quix,taHEQat9MgErQvhG1iRGSJQPfe1SzIemjSyBtB5+hfU=,
,,g0dSW8i7orW7Mb4voYoAGI+v1Lqp0zsEZGBZ6CWSpcjeswHGgXho9HggqTQgT3nnezj/hl6djnePg2LrIBCCkDGpuWAIXerMpyJO0eySSWi8cdNckyMnZZNU3YgaTmmg16mcwn1CQ9O8XO4a9suAovvAmq+6iVMgjK05wKAZORLq01MqIPCxsH9xaoUgBIVDXJcmgu5UlYAYPjcc4tgcAFx9Sph3M697VyI2iyZuD5fvsho7kJZTAqVF4ijRlQ0WHQGWJXKLcQ6OJeBARRPSP9KXODTRMmtJHCMcz6eTclAR5zkGxso+nDXO3dlzwSruEoZxNcV4llAzLH7gvgbfiQ==
">
but was not.
  SecureCsvWriterTest.shouldRotateCsvAndKeyStoreFile:257
Expected size:<6> but was:<8> in:
<[/tmp/SecureCsvWriterTest1681760462361108705/tamper-evident-shouldRotateCsvAndKeyStoreFile.csv-2018.10.21-21.58.20.601,
    /tmp/SecureCsvWriterTest1681760462361108705/tamper-evident-shouldRotateCsvAndKeyStoreFile.csv-2018.10.21-21.58.22.854,
    /tmp/SecureCsvWriterTest1681760462361108705/tamper-evident-shouldRotateCsvAndKeyStoreFile.csv-2018.10.21-21.58.25.709,
    /tmp/SecureCsvWriterTest1681760462361108705/tamper-evident-shouldRotateCsvAndKeyStoreFile.csv-2018.10.21-21.58.28.555,
    /tmp/SecureCsvWriterTest1681760462361108705/tamper-evident-shouldRotateCsvAndKeyStoreFile.csv-2018.10.21-21.58.30.956,
    /tmp/SecureCsvWriterTest1681760462361108705/tamper-evident-shouldRotateCsvAndKeyStoreFile.csv-2018.10.21-21.58.32.947,
    /tmp/SecureCsvWriterTest1681760462361108705/tamper-evident-shouldRotateCsvAndKeyStoreFile.csv-2018.10.21-21.58.34.595,
    /tmp/SecureCsvWriterTest1681760462361108705/tamper-evident-shouldRotateCsvAndKeyStoreFile.csv-2018.10.21-21.58.35.562]>

Tests run: 29, Failures: 2, Errors: 0, Skipped: 0
Kortanul commented 6 years ago

Based on these attempted fixes at this issue downstream in the Open Identity Platform project, it appears that the SecureCsvWriter might be getting blocked waiting on a lock that doesn't get released until after the test has already finished:

Neither of the attempted fixes seem to address the root cause; they appear to be working around it. One of the fixes avoids signing the log line if the lock can't be obtained (this seems bad). The other delays rotation retention checking for 5 minutes, up from the default of 5 seconds (this seems like a kludge).

I am not sure why rotation retention checking should affect CSV signing unless the two functions are sharing a lock and/or the signing should be more aggressive about acquiring the lock.