001// Copyright 2008-2013 The Apache Software Foundation 002// 003// Licensed under the Apache License, Version 2.0 (the "License"); 004// you may not use this file except in compliance with the License. 005// You may obtain a copy of the License at 006// 007// http://www.apache.org/licenses/LICENSE-2.0 008// 009// Unless required by applicable law or agreed to in writing, software 010// distributed under the License is distributed on an "AS IS" BASIS, 011// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 012// See the License for the specific language governing permissions and 013// limitations under the License. 014 015package org.apache.tapestry5.ioc.internal; 016 017import org.apache.tapestry5.ioc.IOOperation; 018import org.apache.tapestry5.ioc.Invokable; 019import org.apache.tapestry5.ioc.OperationTracker; 020import org.apache.tapestry5.ioc.internal.util.CollectionFactory; 021import org.apache.tapestry5.ioc.internal.util.InternalUtils; 022import org.apache.tapestry5.ioc.util.ExceptionUtils; 023import org.apache.tapestry5.ioc.util.Stack; 024import org.slf4j.Logger; 025 026import java.io.IOException; 027 028/** 029 * Core implementation that manages a logger and catches and reports exception. 030 * 031 * @see org.apache.tapestry5.ioc.internal.PerThreadOperationTracker 032 */ 033public class OperationTrackerImpl implements OperationTracker 034{ 035 private final Logger logger; 036 037 private final Stack<String> operations = CollectionFactory.newStack(); 038 039 private boolean logged; 040 041 public OperationTrackerImpl(Logger logger) 042 { 043 this.logger = logger; 044 } 045 046 @Override 047 public void run(String description, final Runnable operation) 048 { 049 assert InternalUtils.isNonBlank(description); 050 assert operation != null; 051 052 long startNanos = start(description); 053 054 try 055 { 056 operation.run(); 057 058 finish(description, startNanos); 059 060 } catch (RuntimeException ex) 061 { 062 logAndRethrow(ex); 063 } catch (Error ex) 064 { 065 handleError(ex); 066 } finally 067 { 068 handleFinally(); 069 } 070 } 071 072 @Override 073 public <T> T invoke(String description, Invokable<T> operation) 074 { 075 assert InternalUtils.isNonBlank(description); 076 assert operation != null; 077 078 long startNanos = start(description); 079 080 try 081 { 082 T result = operation.invoke(); 083 084 finish(description, startNanos); 085 086 return result; 087 088 } catch (RuntimeException ex) 089 { 090 return logAndRethrow(ex); 091 } catch (Error ex) 092 { 093 return handleError(ex); 094 } finally 095 { 096 handleFinally(); 097 } 098 } 099 100 @Override 101 public <T> T perform(String description, IOOperation<T> operation) throws IOException 102 { 103 InternalUtils.isNonBlank(description); 104 assert operation != null; 105 106 long startNanos = start(description); 107 108 try 109 { 110 T result = operation.perform(); 111 112 finish(description, startNanos); 113 114 return result; 115 116 } catch (RuntimeException ex) 117 { 118 return logAndRethrow(ex); 119 } catch (Error ex) 120 { 121 return handleError(ex); 122 } catch (IOException ex) 123 { 124 return logAndRethrow(ex); 125 } finally 126 { 127 handleFinally(); 128 } 129 } 130 131 private void handleFinally() 132 { 133 operations.pop(); 134 // We've finally backed out of the operation stack ... but there may be more to come! 135 136 if (operations.isEmpty()) 137 { 138 logged = false; 139 } 140 } 141 142 private <T> T handleError(Error error) 143 { 144 if (!logged) 145 { 146 log(error); 147 logged = true; 148 } 149 150 throw error; 151 } 152 153 private void finish(String description, long startNanos) 154 { 155 if (logger.isDebugEnabled()) 156 { 157 long elapsedNanos = System.nanoTime() - startNanos; 158 double elapsedMillis = ((double) elapsedNanos) / 1000000.d; 159 160 logger.debug(String.format("[%3d] <-- %s [%,.2f ms]", operations.getDepth(), description, elapsedMillis)); 161 } 162 } 163 164 private long start(String description) 165 { 166 long startNanos = -1l; 167 168 if (logger.isDebugEnabled()) 169 { 170 startNanos = System.nanoTime(); 171 logger.debug(String.format("[%3d] --> %s", operations.getDepth() + 1, description)); 172 } 173 174 operations.push(description); 175 return startNanos; 176 } 177 178 private <T> T logAndRethrow(RuntimeException ex) 179 { 180 if (!logged) 181 { 182 String[] trace = log(ex); 183 184 logged = true; 185 186 throw new OperationException(ex, trace); 187 } 188 189 throw ex; 190 } 191 192 private <T> T logAndRethrow(IOException ex) throws IOException 193 { 194 if (!logged) 195 { 196 String[] trace = log(ex); 197 198 logged = true; 199 200 throw new OperationException(ex, trace); 201 } 202 203 throw ex; 204 } 205 206 private String[] log(Throwable ex) 207 { 208 logger.error(ExceptionUtils.toMessage(ex)); 209 logger.error("Operations trace:"); 210 211 Object[] snapshot = operations.getSnapshot(); 212 String[] trace = new String[snapshot.length]; 213 214 for (int i = 0; i < snapshot.length; i++) 215 { 216 trace[i] = snapshot[i].toString(); 217 218 logger.error(String.format("[%2d] %s", i + 1, trace[i])); 219 } 220 221 return trace; 222 } 223 224 boolean isEmpty() 225 { 226 return operations.isEmpty(); 227 } 228}