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}