Re: Proposal for a new best practice for logging
Thanks, but that is not the link I was referring to. It was an OFBiz Wiki page that listed the debug levels we use in OFBiz and some brief guidelines on when they should be used. -Adrian On 7/14/2012 4:32 AM, Jacques Le Roux wrote: From: Adrian Crum adrian.c...@sandglass-software.com Not long ago, Jacques posted a link to logging best practices in the wiki - but I can't find it now. I was curious about it too. It took me a moment to get it back, but I think this article really is worth it http://architects.dzone.com/articles/high-performance-and-smarter For the impatients, the most interesting part begins (ie is at end as often, but the whole is worth reading) at http://architects.dzone.com/articles/high-performance-and-smarter#_Ref289536806 For your question Jacopo, I'm not sure, this could be configured in debug.properties, because sometimes it's usefull to check data... On the other hand if it's not specific to a sensible part and easily accessible results, like for services which can be easily tested independently using webtools, yes why not. Jacques The wiki page listed logging levels and how they should be used. From what I recall, the information was pretty basic and it could be built out more. -Adrian On 5/30/2012 10:14 AM, Jacopo Cappellato wrote: Would you agree in adopting the following as a best practice for OFBiz logging: do not include full maps/lists in the output or if really necessary limit this to verbose output. For example, avoid code like this: Debug.logInfo(Capture [ + serviceName + ] : + captureContext, module); that generates the following output: [java] 2012-05-30 11:07:42,676 (http-bio-0.0.0.0-8443-exec-4) [PaymentGatewayServices.java:1752:INFO ] Capture [testCCCapture] : {userLogin=[GenericEntity:UserLogin][createdStamp,2012-05-30 11:03:31.383(java.sql.Timestamp)][createdTxStamp,2012-05-30 11:03:31.275(java.sql.Timestamp)][currentPassword,null()][disabledDateTime,null()][enabled,N(java.lang.String)][externalAuthId,null()][hasLoggedOut,null()][isSystem,Y(java.lang.String)][lastCurrencyUom,null()][lastLocale,null()][lastTimeZone,null()][lastUpdatedStamp,2012-05-30 11:03:57.136(java.sql.Timestamp)][lastUpdatedTxStamp,2012-05-30 11:03:57.049(java.sql.Timestamp)][partyId,system(java.lang.String)][passwordHint,null()][requirePasswordChange,null()][successiveFailedLogins,null()][userLdapDn,null()][userLoginId,system(java.lang.String)], orderPaymentPreference=[GenericEntity:OrderPaymentPreference][billingPostalCode,null()][createdByUserLogin,admin(java.lang.String)][createdDate,2008-04-23 16:49:27.966(java.sql.Timestamp)][createdStamp,2012-05-30 11:04:26.446(java.sql.Timestamp)][createdTxStamp,2012-05-30 11:04:25.488(java.sql.Timestamp)][finAccountId,null()][lastUpdatedStamp,2012-05-30 11:07:42.63(java.sql.Timestamp)][lastUpdatedTxStamp,2012-05-30 11:07:38.495(java.sql.Timestamp)][manualAuthCode,null()][manualRefNum,null()][maxAmount,50.85(java.math.BigDecimal)][needsNsfRetry,N(java.lang.String)][orderId,DEMO10090(java.lang.String)][orderItemSeqId,null()][orderPaymentPreferenceId,9000(java.lang.String)][overflowFlag,N(java.lang.String)][paymentMethodId,9015(java.lang.String)][paymentMethodTypeId,CREDIT_CARD(java.lang.String)][presentFlag,N(java.lang.String)][processAttempt,1(java.lang.Long)][productPricePurposeId,null()][securityCode,null()][shipGroupSeqId,null()][statusId,PAYMENT_AUTHORIZED(java.lang.String)][swipedFlag,N(java.lang.String)][track2,null()], paymentConfig=payment.properties, paymentGatewayConfigId=null, currency=USD, captureAmount=50.85, authTrans=[GenericEntity:PaymentGatewayResponse][altReference,1338368862594(java.lang.String)][amount,50.85(java.math.BigDecimal)][createdStamp,2012-05-30 11:07:42.619(java.sql.Timestamp)][createdTxStamp,2012-05-30 11:07:38.495(java.sql.Timestamp)][currencyUomId,USD(java.lang.String)][gatewayAvsResult,null()][gatewayCode,100(java.lang.String)][gatewayCvResult,null()][gatewayFlag,A(java.lang.String)][gatewayMessage,This is a test processor; no payments were captured or authorized.(java.lang.String)][gatewayScoreResult,null()][lastUpdatedStamp,2012-05-30 11:07:42.619(java.sql.Timestamp)][lastUpdatedTxStamp,2012-05-30 11:07:38.495(java.sql.Timestamp)][orderPaymentPreferenceId,9000(java.lang.String)][paymentGatewayResponseId,1(java.lang.String)][paymentMethodId,9015(java.lang.String)][paymentMethodTypeId,CREDIT_CARD(java.lang.String)][paymentServiceTypeEnumId,PRDS_PAY_REAUTH(java.lang.String)][referenceNum,1338368862594(java.lang.String)][resultBadCardNumber,null()][resultBadExpire,null()][resultDeclined,null()][resultNsf,null()][subReference,null()][transCodeEnumId,PGT_AUTHORIZE(java.lang.String)][transactionDate,2012-05-30 11:07:42.619(java.sql.Timestamp)]} If you will agree we could proceed at fixing existing code or at least make sure that new code is clean. Kind regards, Jacopo
Re: Proposal for a new best practice for logging
From: Adrian Crum adrian.c...@sandglass-software.com Not long ago, Jacques posted a link to logging best practices in the wiki - but I can't find it now. I was curious about it too. It took me a moment to get it back, but I think this article really is worth it http://architects.dzone.com/articles/high-performance-and-smarter For the impatients, the most interesting part begins (ie is at end as often, but the whole is worth reading) at http://architects.dzone.com/articles/high-performance-and-smarter#_Ref289536806 For your question Jacopo, I'm not sure, this could be configured in debug.properties, because sometimes it's usefull to check data... On the other hand if it's not specific to a sensible part and easily accessible results, like for services which can be easily tested independently using webtools, yes why not. Jacques The wiki page listed logging levels and how they should be used. From what I recall, the information was pretty basic and it could be built out more. -Adrian On 5/30/2012 10:14 AM, Jacopo Cappellato wrote: Would you agree in adopting the following as a best practice for OFBiz logging: do not include full maps/lists in the output or if really necessary limit this to verbose output. For example, avoid code like this: Debug.logInfo(Capture [ + serviceName + ] : + captureContext, module); that generates the following output: [java] 2012-05-30 11:07:42,676 (http-bio-0.0.0.0-8443-exec-4) [PaymentGatewayServices.java:1752:INFO ] Capture [testCCCapture] : {userLogin=[GenericEntity:UserLogin][createdStamp,2012-05-30 11:03:31.383(java.sql.Timestamp)][createdTxStamp,2012-05-30 11:03:31.275(java.sql.Timestamp)][currentPassword,null()][disabledDateTime,null()][enabled,N(java.lang.String)][externalAuthId,null()][hasLoggedOut,null()][isSystem,Y(java.lang.String)][lastCurrencyUom,null()][lastLocale,null()][lastTimeZone,null()][lastUpdatedStamp,2012-05-30 11:03:57.136(java.sql.Timestamp)][lastUpdatedTxStamp,2012-05-30 11:03:57.049(java.sql.Timestamp)][partyId,system(java.lang.String)][passwordHint,null()][requirePasswordChange,null()][successiveFailedLogins,null()][userLdapDn,null()][userLoginId,system(java.lang.String)], orderPaymentPreference=[GenericEntity:OrderPaymentPreference][billingPostalCode,null()][createdByUserLogin,admin(java.lang.String)][createdDate,2008-04-23 16:49:27.966(java.sql.Timestamp)][createdStamp,2012-05-30 11:04:26.446(java.sql.Timestamp)][createdTxStamp,2012-05-30 11:04:25.488(java.sql.Timestamp)][finAccountId,null()][lastUpdatedStamp,2012-05-30 11:07:42.63(java.sql.Timestamp)][lastUpdatedTxStamp,2012-05-30 11:07:38.495(java.sql.Timestamp)][manualAuthCode,null()][manualRefNum,null()][maxAmount,50.85(java.math.BigDecimal)][needsNsfRetry,N(java.lang.String)][orderId,DEMO10090(java.lang.String)][orderItemSeqId,null()][orderPaymentPreferenceId,9000(java.lang.String)][overflowFlag,N(java.lang.String)][paymentMethodId,9015(java.lang.String)][paymentMethodTypeId,CREDIT_CARD(java.lang.String)][presentFlag,N(java.lang.String)][processAttempt,1(java.lang.Long)][productPricePurposeId,null()][securityCode,null()][shipGroupSeqId,null()][statusId,PAYMENT_AUTHORIZED(java.lang.String)][swipedFlag,N(java.lang.String)][track2,null()], paymentConfig=payment.properties, paymentGatewayConfigId=null, currency=USD, captureAmount=50.85, authTrans=[GenericEntity:PaymentGatewayResponse][altReference,1338368862594(java.lang.String)][amount,50.85(java.math.BigDecimal)][createdStamp,2012-05-30 11:07:42.619(java.sql.Timestamp)][createdTxStamp,2012-05-30 11:07:38.495(java.sql.Timestamp)][currencyUomId,USD(java.lang.String)][gatewayAvsResult,null()][gatewayCode,100(java.lang.String)][gatewayCvResult,null()][gatewayFlag,A(java.lang.String)][gatewayMessage,This is a test processor; no payments were captured or authorized.(java.lang.String)][gatewayScoreResult,null()][lastUpdatedStamp,2012-05-30 11:07:42.619(java.sql.Timestamp)][lastUpdatedTxStamp,2012-05-30 11:07:38.495(java.sql.Timestamp)][orderPaymentPreferenceId,9000(java.lang.String)][paymentGatewayResponseId,1(java.lang.String)][paymentMethodId,9015(java.lang.String)][paymentMethodTypeId,CREDIT_CARD(java.lang.String)][paymentServiceTypeEnumId,PRDS_PAY_REAUTH(java.lang.String)][referenceNum,1338368862594(java.lang.String)][resultBadCardNumber,null()][resultBadExpire,null()][resultDeclined,null()][resultNsf,null()][subReference,null()][transCodeEnumId,PGT_AUTHORIZE(java.lang.String)][transactionDate,2012-05-30 11:07:42.619(java.sql.Timestamp)]} If you will agree we could proceed at fixing existing code or at least make sure that new code is clean. Kind regards, Jacopo
Re: Proposal for a new best practice for logging
Not long ago, Jacques posted a link to logging best practices in the wiki - but I can't find it now. The wiki page listed logging levels and how they should be used. From what I recall, the information was pretty basic and it could be built out more. -Adrian On 5/30/2012 10:14 AM, Jacopo Cappellato wrote: Would you agree in adopting the following as a best practice for OFBiz logging: do not include full maps/lists in the output or if really necessary limit this to verbose output. For example, avoid code like this: Debug.logInfo(Capture [ + serviceName + ] : + captureContext, module); that generates the following output: [java] 2012-05-30 11:07:42,676 (http-bio-0.0.0.0-8443-exec-4) [PaymentGatewayServices.java:1752:INFO ] Capture [testCCCapture] : {userLogin=[GenericEntity:UserLogin][createdStamp,2012-05-30 11:03:31.383(java.sql.Timestamp)][createdTxStamp,2012-05-30 11:03:31.275(java.sql.Timestamp)][currentPassword,null()][disabledDateTime,null()][enabled,N(java.lang.String)][externalAuthId,null()][hasLoggedOut,null()][isSystem,Y(java.lang.String)][lastCurrencyUom,null()][lastLocale,null()][lastTimeZone,null()][lastUpdatedStamp,2012-05-30 11:03:57.136(java.sql.Timestamp)][lastUpdatedTxStamp,2012-05-30 11:03:57.049(java.sql.Timestamp)][partyId,system(java.lang.String)][passwordHint,null()][requirePasswordChange,null()][successiveFailedLogins,null()][userLdapDn,null()][userLoginId,system(java.lang.String)], orderPaymentPreference=[GenericEntity:OrderPaymentPreference][billingPostalCode,null()][createdByUserLogin,admin(java.lang.String)][createdDate,2008-04-23 16:49:27.966(java.sql.Timestamp)][createdStamp,2012-05-30 11:04:26.446(java.sql.Timestamp)][createdTxStamp,2012-05-30 11:04:25.488(java.sql.Timestamp)][finAccountId,null()][lastUpdatedStamp,2012-05-30 11:07:42.63(java.sql.Timestamp)][lastUpdatedTxStamp,2012-05-30 11:07:38.495(java.sql.Timestamp)][manualAuthCode,null()][manualRefNum,null()][maxAmount,50.85(java.math.BigDecimal)][needsNsfRetry,N(java.lang.String)][orderId,DEMO10090(java.lang.String)][orderItemSeqId,null()][orderPaymentPreferenceId,9000(java.lang.String)][overflowFlag,N(java.lang.String)][paymentMethodId,9015(java.lang.String)][paymentMethodTypeId,CREDIT_CARD(java.lang.String)][presentFlag,N(java.lang.String)][processAttempt,1(java.lang.Long)][productPricePurposeId,null()][securityCode,null()][shipGroupSeqId,null()][statusId,PAYMENT_AUTHORIZED(java.lang.String)][swipedFlag,N(java.lang.String)][track2,null()], paymentConfig=payment.properties, paymentGatewayConfigId=null, currency=USD, captureAmount=50.85, authTrans=[GenericEntity:PaymentGatewayResponse][altReference,1338368862594(java.lang.String)][amount,50.85(java.math.BigDecimal)][createdStamp,2012-05-30 11:07:42.619(java.sql.Timestamp)][createdTxStamp,2012-05-30 11:07:38.495(java.sql.Timestamp)][currencyUomId,USD(java.lang.String)][gatewayAvsResult,null()][gatewayCode,100(java.lang.String)][gatewayCvResult,null()][gatewayFlag,A(java.lang.String)][gatewayMessage,This is a test processor; no payments were captured or authorized.(java.lang.String)][gatewayScoreResult,null()][lastUpdatedStamp,2012-05-30 11:07:42.619(java.sql.Timestamp)][lastUpdatedTxStamp,2012-05-30 11:07:38.495(java.sql.Timestamp)][orderPaymentPreferenceId,9000(java.lang.String)][paymentGatewayResponseId,1(java.lang.String)][paymentMethodId,9015(java.lang.String)][paymentMethodTypeId,CREDIT_CARD(java.lang.String)][paymentServiceTypeEnumId,PRDS_PAY_REAUTH(java.lang.String)][referenceNum,1338368862594(java.lang.String)][resultBadCardNumber,null()][resultBadExpire,null()][resultDeclined,null()][resultNsf,null()][subReference,null()][transCodeEnumId,PGT_AUTHORIZE(java.lang.String)][transactionDate,2012-05-30 11:07:42.619(java.sql.Timestamp)]} If you will agree we could proceed at fixing existing code or at least make sure that new code is clean. Kind regards, Jacopo
Re: Proposal for a new best practice for logging
+1. -- Ashish On Wed, May 30, 2012 at 2:44 PM, Jacopo Cappellato jacopo.cappell...@hotwaxmedia.com wrote: Would you agree in adopting the following as a best practice for OFBiz logging: do not include full maps/lists in the output or if really necessary limit this to verbose output. For example, avoid code like this: Debug.logInfo(Capture [ + serviceName + ] : + captureContext, module); that generates the following output: [java] 2012-05-30 11:07:42,676 (http-bio-0.0.0.0-8443-exec-4) [PaymentGatewayServices.java:1752:INFO ] Capture [testCCCapture] : {userLogin=[GenericEntity:UserLogin][createdStamp,2012-05-30 11:03:31.383(java.sql.Timestamp)][createdTxStamp,2012-05-30 11:03:31.275(java.sql.Timestamp)][currentPassword,null()][disabledDateTime,null()][enabled,N(java.lang.String)][externalAuthId,null()][hasLoggedOut,null()][isSystem,Y(java.lang.String)][lastCurrencyUom,null()][lastLocale,null()][lastTimeZone,null()][lastUpdatedStamp,2012-05-30 11:03:57.136(java.sql.Timestamp)][lastUpdatedTxStamp,2012-05-30 11:03:57.049(java.sql.Timestamp)][partyId,system(java.lang.String)][passwordHint,null()][requirePasswordChange,null()][successiveFailedLogins,null()][userLdapDn,null()][userLoginId,system(java.lang.String)], orderPaymentPreference=[GenericEntity:OrderPaymentPreference][billingPostalCode,null()][createdByUserLogin,admin(java.lang.String)][createdDate,2008-04-23 16:49:27.966(java.sql.Timestamp)][createdStamp,2012-05-30 11:04:26.446(java.sql.Timestamp)][createdTxStamp,2012-05-30 11:04:25.488(java.sql.Timestamp)][finAccountId,null()][lastUpdatedStamp,2012-05-30 11:07:42.63(java.sql.Timestamp)][lastUpdatedTxStamp,2012-05-30 11:07:38.495(java.sql.Timestamp)][manualAuthCode,null()][manualRefNum,null()][maxAmount,50.85(java.math.BigDecimal)][needsNsfRetry,N(java.lang.String)][orderId,DEMO10090(java.lang.String)][orderItemSeqId,null()][orderPaymentPreferenceId,9000(java.lang.String)][overflowFlag,N(java.lang.String)][paymentMethodId,9015(java.lang.String)][paymentMethodTypeId,CREDIT_CARD(java.lang.String)][presentFlag,N(java.lang.String)][processAttempt,1(java.lang.Long)][productPricePurposeId,null()][securityCode,null()][shipGroupSeqId,null()][statusId,PAYMENT_AUTHORIZED(java.lang.String)][swipedFlag,N(java.lang.String)][track2,null()], paymentConfig=payment.properties, paymentGatewayConfigId=null, currency=USD, captureAmount=50.85, authTrans=[GenericEntity:PaymentGatewayResponse][altReference,1338368862594(java.lang.String)][amount,50.85(java.math.BigDecimal)][createdStamp,2012-05-30 11:07:42.619(java.sql.Timestamp)][createdTxStamp,2012-05-30 11:07:38.495(java.sql.Timestamp)][currencyUomId,USD(java.lang.String)][gatewayAvsResult,null()][gatewayCode,100(java.lang.String)][gatewayCvResult,null()][gatewayFlag,A(java.lang.String)][gatewayMessage,This is a test processor; no payments were captured or authorized.(java.lang.String)][gatewayScoreResult,null()][lastUpdatedStamp,2012-05-30 11:07:42.619(java.sql.Timestamp)][lastUpdatedTxStamp,2012-05-30 11:07:38.495(java.sql.Timestamp)][orderPaymentPreferenceId,9000(java.lang.String)][paymentGatewayResponseId,1(java.lang.String)][paymentMethodId,9015(java.lang.String)][paymentMethodTypeId,CREDIT_CARD(java.lang.String)][paymentServiceTypeEnumId,PRDS_PAY_REAUTH(java.lang.String)][referenceNum,1338368862594(java.lang.String)][resultBadCardNumber,null()][resultBadExpire,null()][resultDeclined,null()][resultNsf,null()][subReference,null()][transCodeEnumId,PGT_AUTHORIZE(java.lang.String)][transactionDate,2012-05-30 11:07:42.619(java.sql.Timestamp)]} If you will agree we could proceed at fixing existing code or at least make sure that new code is clean. Kind regards, Jacopo
Re: Proposal for a new best practice for logging
On 05/30/2012 04:14 AM, Jacopo Cappellato wrote: Would you agree in adopting the following as a best practice for OFBiz logging: do not include full maps/lists in the output or if really necessary limit this to verbose output. For example, avoid code like this: Debug.logInfo(Capture [ + serviceName + ] : + captureContext, module); Debug.logInfo(Capture [%s] : %s, module, serviceName, captureContext); ps: this has been supported for a while now.
Re: Proposal for a new best practice for logging
On 05/30/2012 04:14 AM, Jacopo Cappellato wrote: Would you agree in adopting the following as a best practice for OFBiz logging: do not include full maps/lists in the output or if really necessary limit this to verbose output. For example, avoid code like this: Debug.logInfo(Capture [ + serviceName + ] : + captureContext, module); Additionally, this is *SUPER BAD NONO DEATH* for PCI compliance. In the following example, it is printing out a CreditCard entity, which is mightly frowned upon. Even if in this case it's an entity that encrypts it's fields during toString(), there may be a parameters in the context that contains an incoming credit card number that is unencrypted. that generates the following output: [java] 2012-05-30 11:07:42,676 (http-bio-0.0.0.0-8443-exec-4) [PaymentGatewayServices.java:1752:INFO ] Capture [testCCCapture] : {userLogin=[GenericEntity:UserLogin][createdStamp,2012-05-30 11:03:31.383(java.sql.Timestamp)][createdTxStamp,2012-05-30 11:03:31.275(java.sql.Timestamp)][currentPassword,null()][disabledDateTime,null()][enabled,N(java.lang.String)][externalAuthId,null()][hasLoggedOut,null()][isSystem,Y(java.lang.String)][lastCurrencyUom,null()][lastLocale,null()][lastTimeZone,null()][lastUpdatedStamp,2012-05-30 11:03:57.136(java.sql.Timestamp)][lastUpdatedTxStamp,2012-05-30 11:03:57.049(java.sql.Timestamp)][partyId,system(java.lang.String)][passwordHint,null()][requirePasswordChange,null()][successiveFailedLogins,null()][userLdapDn,null()][userLoginId,system(java.lang.String)], orderPaymentPreference=[GenericEntity:OrderPaymentPreference][billingPostalCode,null()][createdByUserLogin,admin(java.lang.String)][createdDate,2008-04-23 16:49:27.966(java.sql.Timest amp)][createdStamp,2012-05-30 11:04:26.446(java.sql.Timestamp)][createdTxStamp,2012-05-30 11:04:25.488(java.sql.Timestamp)][finAccountId,null()][lastUpdatedStamp,2012-05-30 11:07:42.63(java.sql.Timestamp)][lastUpdatedTxStamp,2012-05-30 11:07:38.495(java.sql.Timestamp)][manualAuthCode,null()][manualRefNum,null()][maxAmount,50.85(java.math.BigDecimal)][needsNsfRetry,N(java.lang.String)][orderId,DEMO10090(java.lang.String)][orderItemSeqId,null()][orderPaymentPreferenceId,9000(java.lang.String)][overflowFlag,N(java.lang.String)][paymentMethodId,9015(java.lang.String)][paymentMethodTypeId,CREDIT_CARD(java.lang.String)][presentFlag,N(java.lang.String)][processAttempt,1(java.lang.Long)][productPricePurposeId,null()][securityCode,null()][shipGroupSeqId,null()][statusId,PAYMENT_AUTHORIZED(java.lang.String)][swipedFlag,N(java.lang.String)][track2,null()], paymentConfig=payment.properties, paymentGatewayConfigId=null, currency=USD, captureAmount=50.85, authTrans=[GenericEntity:PaymentGa tewayResponse][altReference,1338368862594(java.lang.String)][amount,50.85(java.math.BigDecimal)][createdStamp,2012-05-30 11:07:42.619(java.sql.Timestamp)][createdTxStamp,2012-05-30 11:07:38.495(java.sql.Timestamp)][currencyUomId,USD(java.lang.String)][gatewayAvsResult,null()][gatewayCode,100(java.lang.String)][gatewayCvResult,null()][gatewayFlag,A(java.lang.String)][gatewayMessage,This is a test processor; no payments were captured or authorized.(java.lang.String)][gatewayScoreResult,null()][lastUpdatedStamp,2012-05-30 11:07:42.619(java.sql.Timestamp)][lastUpdatedTxStamp,2012-05-30 11:07:38.495(java.sql.Timestamp)][orderPaymentPreferenceId,9000(java.lang.String)][paymentGatewayResponseId,1(java.lang.String)][paymentMethodId,9015(java.lang.String)][paymentMethodTypeId,CREDIT_CARD(java.lang.String)][paymentServiceTypeEnumId,PRDS_PAY_REAUTH(java.lang.String)][referenceNum,1338368862594(java.lang.String)][resultBadCardNumber,null()][resultBadExpire,null()][resultDeclined,null ()][resultNsf,null()][subReference,null()][transCodeEnumId,PGT_AUTHORIZE(java.lang.String)][transactionDate,2012-05-30 11:07:42.619(java.sql.Timestamp)]} If you will agree we could proceed at fixing existing code or at least make sure that new code is clean. Kind regards, Jacopo
Re: Proposal for a new best practice for logging
On May 30, 2012, at 5:36 PM, Adam Heath wrote: Additionally, this is *SUPER BAD NONO DEATH* for PCI compliance. Right!... and I actually didn't pick this example randomly ;-) Jacopo