resolved bugzilla ticket 53642

git-svn-id: https://svn.apache.org/repos/asf/poi/trunk@1380882 13f79535-47bb-0310-9956-ffa450edef68

src/documentation/content/xdocs/spreadsheet/eval.xml

@@ -42,7 +42,7 @@
 		<section><title>Status</title>
 			<p>	The code currently provides implementations for all the arithmatic operators.
 				It also provides implementations for approx. 140 built in
-				functions in Excel. The framework however makes is easy to add 
+				functions in Excel. The framework however makes it easy to add 
 			 	implementation of new functions. See the <link href="eval-devguide.html"> Formula
         evaluation development guide</link>  and <link href="../apidocs/org/apache/poi/hssf/record/formula/functions/package-summary.html">javadocs</link> 
         for details. </p>
@@ -249,7 +249,7 @@ for(int sheetNum = 0; sheetNum &lt; wb.getNumberOfSheets(); sheetNum++) {
         existing workbooks with formulas. This can be done in two ways:  
       </p>   
       <p>
-        1. Re-evaluate  formuals with POI's FormulaEvaluator:
+        1. Re-evaluate  formulas with POI's FormulaEvaluator:
       </p>   
         <source>
   Workbook wb = WorkbookFactory.create(new FileInputStream("workbook.xls"));
@@ -308,5 +308,33 @@ for(int sheetNum = 0; sheetNum &lt; wb.getNumberOfSheets(); sheetNum++) {
         </li>
       </ul>
     </section>
+    <section><title>Formula Evaluation Debugging</title>
+		<p>POI is not perfect and you may stumble across formula evaluation problems (Java exceptions
+		or just different results) in your special use case. To support an easy detailed analysis, a special
+		logging of the full evaluation is provided.</p>
+		<p>The output of this logging may be very large (depends on your EXCEL), so this logging has to be explicitly enabled
+		for each single formula evaluation. Should not be used in production - only for specific development use.</p>
+		<p>Example use:</p>
+		<source>
+	// activate logging to console
+	System.setProperty("org.apache.poi.util.POILogger", "org.apache.poi.util.SystemOutLogger");
+	System.setProperty("poi.log.level", POILogger.INFO + "");
+	
+	// open your file
+	Workbook wb = new HSSFWorkbook(new FileInputStream("foobar.xls"));
+    HSSFFormulaEvaluator fe = (HSSFFormulaEvaluator) wb.getCreationHelper().createFormulaEvaluator();
+
+	// get your cell
+	Cell cell = wb.getSheet(0).getRow(0).getCell(0);		// just a dummy example
+
+	// perform debug output for the next evaluate-call only
+    fe.setDebugEvaluationOutputForNextEval(true);
+	evaluator.evaluateFormulaCell(cell);
+	evaluator.evaluateFormulaCell(cell);		// no logging performed for this next evaluate-call
+		</source>
+		<p>The special Logger called "POI.FormulaEval" is used (useful if you use the CommonsLogger and a detailed logging configuration).
+		The used log levels are WARN and INFO (for detailed parameter info and results) - the level are so high to allow this
+		special logging without beeing disturbed by the bunch of DEBUG log entries from other classes.</p>
+	</section>
   </body>
 </document>

src/java/org/apache/poi/hssf/usermodel/HSSFFormulaEvaluator.java

@@ -389,4 +389,15 @@ public class HSSFFormulaEvaluator implements FormulaEvaluator  {
         _bookEvaluator.setIgnoreMissingWorkbooks(ignore);
     }
 
+    /**
+     * @param value whether perform detailed output
+     *
+     * Perform detailed output of formula evaluation for next evaluation only?
+     * Is for developer use only (also developers using POI for their XLS files).
+     * Log-Level WARN is for basic info, INFO for detailed information. These quite
+     * high levels are used because you have to explicitly enable this specific logging.
+     */
+    public void setDebugEvaluationOutputForNextEval(boolean value){
+        _bookEvaluator.setDebugEvaluationOutputForNextEval(value);
+    }
 }

src/java/org/apache/poi/hssf/usermodel/HSSFSheet.java

@@ -171,9 +171,10 @@ public final class HSSFSheet implements org.apache.poi.ss.usermodel.Sheet {
         Iterator<CellValueRecordInterface> iter = sheet.getCellValueIterator();
         long timestart = System.currentTimeMillis();
 
-        if (log.check(POILogger.DEBUG))
+        if (log.check( POILogger.DEBUG )) {
             log.log(DEBUG, "Time at start of cell creating in HSSF sheet = ",
                     Long.valueOf(timestart));
+        }
         HSSFRow lastrow = null;
 
         // Add every cell to its row
@@ -199,17 +200,24 @@ public final class HSSFSheet implements org.apache.poi.ss.usermodel.Sheet {
                     hrow = createRowFromRecord(rowRec);
                 }
             }
-            if (log.check(POILogger.DEBUG))
-                log.log(DEBUG, "record id = " + Integer.toHexString(((Record) cval).getSid()));
-            hrow.createCellFromRecord(cval);
-            if (log.check(POILogger.DEBUG))
-                log.log(DEBUG, "record took ",
-                        Long.valueOf(System.currentTimeMillis() - cellstart));
+            if (log.check( POILogger.DEBUG )) {
+            	if (cval instanceof Record) {
+                log.log( DEBUG, "record id = " + Integer.toHexString( ( (Record) cval ).getSid() ) );
+				} else {
+					log.log( DEBUG, "record = " + cval );
+				}
+            }
+            hrow.createCellFromRecord( cval );
+            if (log.check( POILogger.DEBUG )) {
+                log.log( DEBUG, "record took ",
+                    Long.valueOf( System.currentTimeMillis() - cellstart ) );
+			}
 
         }
-        if (log.check(POILogger.DEBUG))
+        if (log.check( POILogger.DEBUG )) {
             log.log(DEBUG, "total sheet cell creation took ",
-                    Long.valueOf(System.currentTimeMillis() - timestart));
+                Long.valueOf(System.currentTimeMillis() - timestart));
+    }
     }
 
     /**

src/java/org/apache/poi/ss/formula/WorkbookEvaluator.java

@@ -70,6 +70,7 @@ import org.apache.poi.util.POILogger;
  * For POI internal use only
  *
  * @author Josh Micich
+ * @author Thies Wellpott (debug output enhancements)
  */
 public final class WorkbookEvaluator {
 	
@@ -384,14 +385,47 @@ public final class WorkbookEvaluator {
 		}
 		throw new RuntimeException("Unexpected cell type (" + cellType + ")");
 	}
+
+
+    /**
+     * whether print detailed messages about the next formula evaluation
+     */
+	private boolean dbgEvaluationOutputForNextEval = false;
+
+	// special logger for formula evaluation output (because of possibly very large output)
+	private final POILogger EVAL_LOG = POILogFactory.getLogger("POI.FormulaEval");
+	// current indent level for evalution; negative value for no output
+	private int dbgEvaluationOutputIndent = -1;
+
 	// visibility raised for testing
 	/* package */ ValueEval evaluateFormula(OperationEvaluationContext ec, Ptg[] ptgs) {
 
+		String dbgIndentStr = "";		// always init. to non-null just for defensive avoiding NPE
+		if (dbgEvaluationOutputForNextEval) {
+			// first evaluation call when ouput is desired, so iit. this evaluator instance
+			dbgEvaluationOutputIndent = 1;
+			dbgEvaluationOutputForNextEval = false;
+		}
+		if (dbgEvaluationOutputIndent > 0) {
+			// init. indent string to needed spaces (create as substring vom very long space-only string;
+			// limit indendation for deep recursions)
+			dbgIndentStr = "                                                                                                    ";
+			dbgIndentStr = dbgIndentStr.substring(0, Math.min(dbgIndentStr.length(), dbgEvaluationOutputIndent*2));
+			EVAL_LOG.log(POILogger.WARN, dbgIndentStr
+			                   + "- evaluateFormula('" + ec.getRefEvaluatorForCurrentSheet().getSheetName()
+			                   + "'/" + new CellReference(ec.getRowIndex(), ec.getColumnIndex()).formatAsString()
+			                   + "): " + Arrays.toString(ptgs).replaceAll("\\Qorg.apache.poi.ss.formula.ptg.\\E", ""));
+			dbgEvaluationOutputIndent++;
+		}
+
 		Stack<ValueEval> stack = new Stack<ValueEval>();
 		for (int i = 0, iSize = ptgs.length; i < iSize; i++) {
 
 			// since we don't know how to handle these yet :(
 			Ptg ptg = ptgs[i];
+			if (dbgEvaluationOutputIndent > 0) {
+				EVAL_LOG.log(POILogger.INFO, dbgIndentStr + "  * ptg " + i + ": " + ptg);
+			}
 			if (ptg instanceof AttrPtg) {
 				AttrPtg attrPtg = (AttrPtg) ptg;
 				if (attrPtg.isSum()) {
@@ -497,13 +531,28 @@ public final class WorkbookEvaluator {
 			}
 //			logDebug("push " + opResult);
 			stack.push(opResult);
+			if (dbgEvaluationOutputIndent > 0) {
+				EVAL_LOG.log(POILogger.INFO, dbgIndentStr + "    = " + opResult);
+			}
 		}
 
 		ValueEval value = stack.pop();
 		if (!stack.isEmpty()) {
 			throw new IllegalStateException("evaluation stack not empty");
 		}
-		return dereferenceResult(value, ec.getRowIndex(), ec.getColumnIndex());
+		ValueEval result = dereferenceResult(value, ec.getRowIndex(), ec.getColumnIndex());
+		if (dbgEvaluationOutputIndent > 0) {
+			EVAL_LOG.log(POILogger.INFO, dbgIndentStr + "finshed eval of "
+							+ new CellReference(ec.getRowIndex(), ec.getColumnIndex()).formatAsString()
+							+ ": " + result);
+			dbgEvaluationOutputIndent--;
+			if (dbgEvaluationOutputIndent == 1) {
+				// this evaluation is done, reset indent to stop logging
+				dbgEvaluationOutputIndent = -1;
+			}
+		} // if
+		return result;
+
 	}
 
 	/**
@@ -723,4 +772,8 @@ public final class WorkbookEvaluator {
     public static void registerFunction(String name, Function func){
         FunctionEval.registerFunction(name, func);
     }
+
+    public void setDebugEvaluationOutputForNextEval(boolean value){
+        dbgEvaluationOutputForNextEval = value;
+    }
 }

src/java/org/apache/poi/util/POILogger.java

@@ -17,7 +17,8 @@
 
 package org.apache.poi.util;
 
-import java.util.*;
+import java.util.ArrayList;
+import java.util.List;
 
 /**
  * A logger interface that strives to make it as easy as possible for
@@ -31,11 +32,17 @@ import java.util.*;
  */
 public abstract class POILogger {
 
-    public static int DEBUG = 1;
-    public static int INFO  = 3;
-    public static int WARN  = 5;
-    public static int ERROR = 7;
-    public static int FATAL = 9;
+    public static final int DEBUG = 1;
+    public static final int INFO  = 3;
+    public static final int WARN  = 5;
+    public static final int ERROR = 7;
+    public static final int FATAL = 9;
+
+    /** Short strings for numeric log level. Use level as array index. */
+    protected static final String LEVEL_STRINGS_SHORT[] = {"?", "D", "?", "I", "?", "W", "?", "E", "?", "F", "?"};
+    /** Long strings for numeric log level. Use level as array index. */
+    protected static final String LEVEL_STRINGS[] = {"?0?", "DEBUG", "?2?", "INFO", "?4?", "WARN", "?6?", "ERROR", "?8?", "FATAL", "?10+?"};
+
 
     /**
      * package scope so it cannot be instantiated outside of the util

src/java/org/apache/poi/util/SystemOutLogger.java

@@ -60,8 +60,8 @@ public class SystemOutLogger extends POILogger
     public void log(final int level, final Object obj1,
                     final Throwable exception) {
         if (check(level)) {
-            System.out.println("["+_cat+"] "+obj1);
-            if(exception != null) {
+            System.out.println("[" + _cat + "]" + LEVEL_STRINGS_SHORT[Math.min(LEVEL_STRINGS_SHORT.length-1, level)] + " " + obj1);
+            if (exception != null) {
             	exception.printStackTrace(System.out);
             }
         }