From f518ed4b41f0be20c56e4277a8e138278befa145 Mon Sep 17 00:00:00 2001 From: Jeremiah Gowdy Date: Tue, 3 Oct 2023 09:34:57 -0700 Subject: [PATCH] Significantly improve logging, make error logs not conditional on verbose --- internal/asherah/asherah.go | 12 ++++++++++ internal/output/output.go | 6 ++--- libasherah.go | 46 +++++++++++++++++++++++++++---------- 3 files changed, 49 insertions(+), 15 deletions(-) diff --git a/internal/asherah/asherah.go b/internal/asherah/asherah.go index 7c5e421..4cbdd8a 100644 --- a/internal/asherah/asherah.go +++ b/internal/asherah/asherah.go @@ -7,6 +7,7 @@ import ( "github.com/aws/aws-sdk-go/aws" awssession "github.com/aws/aws-sdk-go/aws/session" + "github.com/godaddy/asherah-cobhan/internal/output" "github.com/godaddy/asherah/go/appencryption" "github.com/godaddy/asherah/go/appencryption/pkg/crypto/aead" "github.com/godaddy/asherah/go/appencryption/pkg/kms" @@ -23,6 +24,7 @@ var ErrAsherahFailedInitialization = errors.New("asherah failed initialization") func Setup(options *Options) error { if atomic.LoadInt32(&globalInitialized) == 1 { + output.StderrDebugOutputf("Failed to initialize asherah: already initialized") return ErrAsherahAlreadyInitialized } @@ -58,6 +60,7 @@ func Setup(options *Options) error { ) if globalSessionFactory == nil { + output.StderrDebugOutputf("Failed to create session factory") return ErrAsherahFailedInitialization } @@ -74,11 +77,13 @@ func Shutdown() { func Encrypt(partitionId string, data []byte) (*appencryption.DataRowRecord, error) { if globalInitialized == 0 { + output.StderrDebugOutputf("Failed to encrypt data: asherah is not initialized") return nil, ErrAsherahNotInitialized } session, err := globalSessionFactory.GetSession(partitionId) if err != nil { + output.StderrDebugOutputf("Failed to get session for partition %v: %v", partitionId, err) return nil, err } defer session.Close() @@ -94,6 +99,7 @@ func Decrypt(partitionId string, drr *appencryption.DataRowRecord) ([]byte, erro session, err := globalSessionFactory.GetSession(partitionId) if err != nil { + output.StderrDebugOutputf("Failed to get session for partition %v: %v", partitionId, err) return nil, err } defer session.Close() @@ -108,6 +114,7 @@ func NewMetastore(opts *Options) appencryption.Metastore { // TODO: support other databases db, err := newMysql(opts.ConnectionString) if err != nil { + output.StderrDebugOutputf("PANIC: Failed to connect to database: %v", err) panic(err) } @@ -115,6 +122,7 @@ func NewMetastore(opts *Options) appencryption.Metastore { if len(opts.ReplicaReadConsistency) > 0 { err := setRdbmsReplicaReadConsistencyValue(opts.ReplicaReadConsistency) if err != nil { + output.StderrDebugOutputf("PANIC: Failed to set replica read consistency: %v", err) panic(err) } } @@ -145,8 +153,11 @@ func NewMetastore(opts *Options) appencryption.Metastore { func NewKMS(opts *Options, crypto appencryption.AEAD) appencryption.KeyManagementService { if opts.KMS == "static" { + output.StderrDebugOutputf("*** WARNING WARNING WARNING USING STATIC MASTER KEY - THIS IS FOR DEBUG ONLY ***") + m, err := kms.NewStatic("thisIsAStaticMasterKeyForTesting", aead.NewAES256GCM()) if err != nil { + output.StderrDebugOutputf("PANIC: Failed to create static master key: %v", err) panic(err) } @@ -155,6 +166,7 @@ func NewKMS(opts *Options, crypto appencryption.AEAD) appencryption.KeyManagemen m, err := kms.NewAWS(crypto, opts.PreferredRegion, opts.RegionMap) if err != nil { + output.StderrDebugOutputf("PANIC: Failed to create AWS KMS: %v", err) panic(err) } diff --git a/internal/output/output.go b/internal/output/output.go index c56b553..dd8a09a 100644 --- a/internal/output/output.go +++ b/internal/output/output.go @@ -12,7 +12,7 @@ func EnableVerboseOutput(flag bool) { if flag { VerboseOutput = StderrDebugOutput VerboseOutputf = StderrDebugOutputf - VerboseOutput("Enabled debug output") + VerboseOutput("asherah-cobhan: Enabled debug output") } else { VerboseOutput = NullDebugOutput VerboseOutputf = NullDebugOutputf @@ -20,11 +20,11 @@ func EnableVerboseOutput(flag bool) { } func StderrDebugOutput(output interface{}) { - fmt.Fprintf(os.Stderr, "%#v\n", output) + fmt.Fprintf(os.Stderr, "asherah-cobhan: %#v\n", output) } func StderrDebugOutputf(format string, args ...interface{}) { - fmt.Fprintf(os.Stderr, format+"\n", args...) + fmt.Fprintf(os.Stderr, "asherah-cobhan:"+format+"\n", args...) } func NullDebugOutput(output interface{}) { diff --git a/libasherah.go b/libasherah.go index 355ae0b..d74b2a1 100644 --- a/libasherah.go +++ b/libasherah.go @@ -23,6 +23,8 @@ func main() { //export Shutdown func Shutdown() { + output.VerboseOutput("Asherah shutdown") + asherah.Shutdown() } @@ -42,6 +44,7 @@ func SetEnv(envJson unsafe.Pointer) int32 { result := cobhan.BufferToJsonStruct(envJson, &env) if result != cobhan.ERR_NONE { + output.StderrDebugOutputf("Failed to deserialize environment JSON string %v", result) return result } @@ -61,6 +64,7 @@ func SetupJson(configJson unsafe.Pointer) int32 { output.StderrDebugOutputf("Failed to deserialize configuration string %v", result) configString, stringResult := cobhan.BufferToString(configJson) if stringResult != cobhan.ERR_NONE { + output.StderrDebugOutputf("Could not convert configJson to string: %v", stringResult) return result } output.StderrDebugOutputf("Could not deserialize: %v", configString) @@ -75,11 +79,16 @@ func SetupJson(configJson unsafe.Pointer) int32 { err := asherah.Setup(options) if err == asherah.ErrAsherahAlreadyInitialized { + output.StderrDebugOutput("Setup failed: asherah is already initialized") return ERR_ALREADY_INITIALIZED } if err != nil { + output.StderrDebugOutput("Setup failed due to bad config?") return ERR_BAD_CONFIG } + + output.VerboseOutput("Successfully configured asherah") + return cobhan.ERR_NONE } @@ -99,16 +108,19 @@ func Decrypt(partitionIdPtr unsafe.Pointer, encryptedDataPtr unsafe.Pointer, enc created int64, parentKeyIdPtr unsafe.Pointer, parentKeyCreated int64, outputDecryptedDataPtr unsafe.Pointer) int32 { encryptedData, result := cobhan.BufferToBytes(encryptedDataPtr) if result != cobhan.ERR_NONE { + output.StderrDebugOutputf("Failed to convert encryptedDataPtr cobhan buffer to bytes %v", result) return result } encryptedKey, result := cobhan.BufferToBytes(encryptedKeyPtr) if result != cobhan.ERR_NONE { + output.StderrDebugOutputf("Failed to convert encryptedKeyPtr cobhan buffer to bytes %v", result) return result } parentKeyId, result := cobhan.BufferToString(parentKeyIdPtr) if result != cobhan.ERR_NONE { + output.StderrDebugOutputf("Failed to convert parentKeyIdPtr cobhan buffer to string %v", result) return result } @@ -126,6 +138,7 @@ func Decrypt(partitionIdPtr unsafe.Pointer, encryptedDataPtr unsafe.Pointer, enc data, result := decryptData(partitionIdPtr, &drr) if result != cobhan.ERR_NONE { + output.StderrDebugOutputf("Failed to decrypt data %v", result) return result } @@ -139,37 +152,38 @@ func Encrypt(partitionIdPtr unsafe.Pointer, dataPtr unsafe.Pointer, outputEncryp drr, result := encryptData(partitionIdPtr, dataPtr) if result != cobhan.ERR_NONE { + output.StderrDebugOutputf("Failed to encrypt data %v", result) return result } result = cobhan.BytesToBuffer(drr.Data, outputEncryptedDataPtr) if result != cobhan.ERR_NONE { - output.VerboseOutputf("Encrypted data length: %v", len(drr.Data)) - output.VerboseOutputf("Encrypt: BytesToBuffer returned %v for outputEncryptedDataPtr", result) + output.StderrDebugOutputf("Encrypted data length: %v", len(drr.Data)) + output.StderrDebugOutputf("Encrypt: BytesToBuffer returned %v for outputEncryptedDataPtr", result) return result } result = cobhan.BytesToBuffer(drr.Key.EncryptedKey, outputEncryptedKeyPtr) if result != cobhan.ERR_NONE { - output.VerboseOutputf("Encrypt: BytesToBuffer returned %v for outputEncryptedKeyPtr", result) + output.StderrDebugOutputf("Encrypt: BytesToBuffer returned %v for outputEncryptedKeyPtr", result) return result } result = cobhan.Int64ToBuffer(drr.Key.Created, outputCreatedPtr) if result != cobhan.ERR_NONE { - output.VerboseOutputf("Encrypt: Int64ToBuffer returned %v for outputCreatedPtr", result) + output.StderrDebugOutputf("Encrypt: Int64ToBuffer returned %v for outputCreatedPtr", result) return result } result = cobhan.StringToBuffer(drr.Key.ParentKeyMeta.ID, outputParentKeyIdPtr) if result != cobhan.ERR_NONE { - output.VerboseOutputf("Encrypt: BytesToBuffer returned %v for outputParentKeyIdPtr", result) + output.StderrDebugOutputf("Encrypt: BytesToBuffer returned %v for outputParentKeyIdPtr", result) return result } result = cobhan.Int64ToBuffer(drr.Key.ParentKeyMeta.Created, outputParentKeyCreatedPtr) if result != cobhan.ERR_NONE { - output.VerboseOutputf("Encrypt: BytesToBuffer returned %v for outputParentKeyCreatedPtr", result) + output.StderrDebugOutputf("Encrypt: BytesToBuffer returned %v for outputParentKeyCreatedPtr", result) return result } @@ -180,6 +194,7 @@ func Encrypt(partitionIdPtr unsafe.Pointer, dataPtr unsafe.Pointer, outputEncryp func EncryptToJson(partitionIdPtr unsafe.Pointer, dataPtr unsafe.Pointer, jsonPtr unsafe.Pointer) int32 { drr, result := encryptData(partitionIdPtr, dataPtr) if result != cobhan.ERR_NONE { + output.StderrDebugOutputf("Failed to encrypt data %v", result) return result } @@ -188,11 +203,11 @@ func EncryptToJson(partitionIdPtr unsafe.Pointer, dataPtr unsafe.Pointer, jsonPt if result == cobhan.ERR_BUFFER_TOO_SMALL { outputBytes, err := json.Marshal(drr) if err == nil { - output.VerboseOutputf("EncryptToJson: JsonToBuffer: Output buffer needed %v bytes", len(outputBytes)) + output.StderrDebugOutputf("EncryptToJson: JsonToBuffer: Output buffer needed %v bytes", len(outputBytes)) return result } } - output.VerboseOutputf("EncryptToJson: JsonToBuffer returned %v for jsonPtr", result) + output.StderrDebugOutputf("EncryptToJson: JsonToBuffer returned %v for jsonPtr", result) return result } @@ -204,21 +219,23 @@ func DecryptFromJson(partitionIdPtr unsafe.Pointer, jsonPtr unsafe.Pointer, data var drr appencryption.DataRowRecord result := cobhan.BufferToJsonStruct(jsonPtr, &drr) if result != cobhan.ERR_NONE { + output.StderrDebugOutputf("Failed to convert cobhan buffer to JSON structs %v", result) return result } data, result := decryptData(partitionIdPtr, &drr) if result != cobhan.ERR_NONE { + output.StderrDebugOutputf("Failed to decrypt data %v", result) return result } result = cobhan.BytesToBuffer(data, dataPtr) if result != cobhan.ERR_NONE { if result == cobhan.ERR_BUFFER_TOO_SMALL { - output.VerboseOutputf("DecryptFromJson: BytesToBuffer: Output buffer needed %v bytes", len(data)) + output.StderrDebugOutputf("DecryptFromJson: BytesToBuffer: Output buffer needed %v bytes", len(data)) return result } - output.VerboseOutputf("DecryptFromJson: BytesToBuffer returned %v for dataPtr", result) + output.StderrDebugOutputf("DecryptFromJson: BytesToBuffer returned %v for dataPtr", result) return result } @@ -228,20 +245,23 @@ func DecryptFromJson(partitionIdPtr unsafe.Pointer, jsonPtr unsafe.Pointer, data func encryptData(partitionIdPtr unsafe.Pointer, dataPtr unsafe.Pointer) (*appencryption.DataRowRecord, int32) { partitionId, result := cobhan.BufferToString(partitionIdPtr) if result != cobhan.ERR_NONE { + output.StderrDebugOutputf("Failed to convert cobhan buffer to string %v", result) return nil, result } data, result := cobhan.BufferToBytes(dataPtr) if result != cobhan.ERR_NONE { + output.StderrDebugOutputf("Failed to convert cobhan buffer to bytes %v", result) return nil, result } drr, err := asherah.Encrypt(partitionId, data) if err != nil { if err == asherah.ErrAsherahNotInitialized { + output.StderrDebugOutput("Encrypt failed: asherah is not initialized") return nil, ERR_NOT_INITIALIZED } - output.VerboseOutputf("Encrypt failed: %v", err) + output.StderrDebugOutputf("Encrypt failed: %v", err) return nil, ERR_ENCRYPT_FAILED } @@ -251,15 +271,17 @@ func encryptData(partitionIdPtr unsafe.Pointer, dataPtr unsafe.Pointer) (*appenc func decryptData(partitionIdPtr unsafe.Pointer, drr *appencryption.DataRowRecord) ([]byte, int32) { partitionId, result := cobhan.BufferToString(partitionIdPtr) if result != cobhan.ERR_NONE { + output.StderrDebugOutputf("Failed to convert cobhan buffer to string %v", result) return nil, result } data, err := asherah.Decrypt(partitionId, drr) if err != nil { if err == asherah.ErrAsherahNotInitialized { + output.StderrDebugOutput("Decrypt failed: asherah is not initialized") return nil, ERR_NOT_INITIALIZED } - output.VerboseOutputf("Decrypt failed: %v", err) + output.StderrDebugOutputf("Decrypt failed: %v", err) return nil, ERR_DECRYPT_FAILED }