001// Copyright 2008-2013, 2023 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.commons.util.CollectionFactory; 018import org.apache.tapestry5.commons.util.ExceptionUtils; 019import org.apache.tapestry5.commons.util.Stack; 020import org.apache.tapestry5.ioc.IOOperation; 021import org.apache.tapestry5.ioc.Invokable; 022import org.apache.tapestry5.ioc.OperationTracker; 023import org.apache.tapestry5.ioc.internal.util.InternalUtils; 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 handleRuntimeException(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 handleRuntimeException(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 <T> T handleRuntimeException(RuntimeException ex) 132 { 133 // This is to prevent the error level log messages 134 if (ExceptionUtils.isAnnotationInStackTrace(ex, NonLoggableException.class)) 135 // pass through without logging 136 throw ex; 137 else 138 return logAndRethrow(ex); 139 } 140 141 private void handleFinally() 142 { 143 operations.pop(); 144 // We've finally backed out of the operation stack ... but there may be more to come! 145 146 if (operations.isEmpty()) 147 { 148 logged = false; 149 } 150 } 151 152 private <T> T handleError(Error error) 153 { 154 if (!logged) 155 { 156 log(error); 157 logged = true; 158 } 159 160 throw error; 161 } 162 163 private void finish(String description, long startNanos) 164 { 165 if (logger.isDebugEnabled()) 166 { 167 long elapsedNanos = System.nanoTime() - startNanos; 168 double elapsedMillis = ((double) elapsedNanos) / 1000000.d; 169 170 logger.debug(String.format("[%3d] <-- %s [%,.2f ms]", operations.getDepth(), description, elapsedMillis)); 171 } 172 } 173 174 private long start(String description) 175 { 176 long startNanos = -1l; 177 178 if (logger.isDebugEnabled()) 179 { 180 startNanos = System.nanoTime(); 181 logger.debug(String.format("[%3d] --> %s", operations.getDepth() + 1, description)); 182 } 183 184 operations.push(description); 185 return startNanos; 186 } 187 188 private <T> T logAndRethrow(RuntimeException ex) 189 { 190 if (!logged) 191 { 192 String[] trace = log(ex); 193 194 logged = true; 195 196 throw new OperationException(ex, trace); 197 } 198 199 throw ex; 200 } 201 202 private <T> T logAndRethrow(IOException ex) throws IOException 203 { 204 if (!logged) 205 { 206 String[] trace = log(ex); 207 208 logged = true; 209 210 throw new OperationException(ex, trace); 211 } 212 213 throw ex; 214 } 215 216 private String[] log(Throwable ex) 217 { 218 logger.error(ExceptionUtils.toMessage(ex)); 219 logger.error("Operations trace:"); 220 221 Object[] snapshot = operations.getSnapshot(); 222 String[] trace = new String[snapshot.length]; 223 224 for (int i = 0; i < snapshot.length; i++) 225 { 226 trace[i] = snapshot[i].toString(); 227 228 logger.error(String.format("[%2d] %s", i + 1, trace[i])); 229 } 230 231 return trace; 232 } 233 234 boolean isEmpty() 235 { 236 return operations.isEmpty(); 237 } 238}