    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}