MINOR: spoe: Add counters to log info about SPOE agents

In addition to metrics about time spent in the SPOE, following counters have
been added:

  * applets : number of SPOE applets.
  * idles : number of idle applets.
  * nb_sending : number of streams waiting to send data.
  * nb_waiting : number of streams waiting for a ack.
  * nb_processed : number of events/groups processed by the SPOE (from the
                   stream point of view).
  * nb_errors : number of errors during the processing (from the stream point of
                view).

Log messages has been updated to report these counters. Following pattern has
been added at the end of the log message:

    ... <idles>/<applets> <nb_sending>/<nb_waiting> <nb_error>/<nb_processed>

diff --git a/doc/SPOE.txt b/doc/SPOE.txt
index 016590e3f6f5d8296ec3d4a1d1d20c0e286100ff..756988f682a4babac426e28e3e029c0f3bfc3c2f 100644 (file)
--- a/doc/SPOE.txt
+++ b/doc/SPOE.txt
@@ -1200,7 +1200,8 @@ LOG_NOTICE. Otherwise, the message is logged with the level LOG_WARNING.
 The messages are logged using the agent's logger, if defined, and use the
 following format:
 
-    SPOE: [AGENT] <TYPE:NAME> sid=STREAM-ID st=STATUC-CODE reqT/qT/wT/resT/pT
+    SPOE: [AGENT] <TYPE:NAME> sid=STREAM-ID st=STATUC-CODE reqT/qT/wT/resT/pT \
+    <idles>/<applets> <nb_sending>/<nb_waiting> <nb_error>/<nb_processed>
 
       AGENT              is the agent name
       TYPE               is EVENT of GROUP
@@ -1221,6 +1222,14 @@ following format:
                  point of view, it is the latency added by the SPOE processing.
                  It is more or less the sum of values above.
 
+      <idle>             is the numbers of idle SPOE applets
+      <applets>          is the numbers of SPOE applets
+      <nb_sending>       is the numbers of streams waiting to send data
+      <nb_waiting>       is the numbers of streams waiting for a ack
+      <nb_error>         is the numbers of processing errors
+      <nb_processed>     is the numbers of events/groups processed
+
+
 For all these time events, -1 means the processing was interrupted before the
 end. So -1 for the queue time means the request was never dequeued. For
 fragmented frames it is harder to know when the interruption happened.

diff --git a/include/types/spoe.h b/include/types/spoe.h
index b7d54f344d407b0d6ae9396dce5c35cb13ddad5e..c01a03efb1751da9ffdf5ecf884086c4c5317e9b 100644 (file)
--- a/include/types/spoe.h
+++ b/include/types/spoe.h
@@ -282,6 +282,14 @@ struct spoe_agent {
                __decl_hathreads(HA_SPINLOCK_T lock);
        } *rt;
 
+       struct {
+               unsigned int applets;            /* # of SPOE applets */
+               unsigned int idles;              /* # of idle applets */
+               unsigned int nb_sending;         /* # of streams waiting to send data */
+               unsigned int nb_waiting;         /* # of streams waiting for a ack */
+               unsigned long long nb_processed; /* # of frames processed by the SPOE */
+               unsigned long long nb_errors;    /* # of errors during the processing */
+       } counters;
 };
 
 /* SPOE filter configuration */

diff --git a/src/flt_spoe.c b/src/flt_spoe.c
index 3b425cc3cf44bb6347f9a34a206c9b1c11e715fe..7c019c412505b15c7ad1a2728f34eb5d43fbea05 100644 (file)
--- a/src/flt_spoe.c
+++ b/src/flt_spoe.c
@@ -1233,6 +1233,7 @@ spoe_release_appctx(struct appctx *appctx)
 
        /* Remove applet from the list of running applets */
        SPOE_DEBUG_STMT(agent->rt[tid].applets_act--);
+       HA_ATOMIC_SUB(&agent->counters.applets, 1);
        HA_SPIN_LOCK(SPOE_APPLET_LOCK, &agent->rt[tid].lock);
        if (!LIST_ISEMPTY(&spoe_appctx->list)) {
                LIST_DEL(&spoe_appctx->list);
@@ -1245,6 +1246,7 @@ spoe_release_appctx(struct appctx *appctx)
                if (appctx->st0 == SPOE_APPCTX_ST_IDLE) {
                        eb32_delete(&spoe_appctx->node);
                        SPOE_DEBUG_STMT(agent->rt[tid].applets_idle--);
+                       HA_ATOMIC_SUB(&agent->counters.idles, 1);
                }
 
                appctx->st0 = SPOE_APPCTX_ST_END;
@@ -1266,6 +1268,7 @@ spoe_release_appctx(struct appctx *appctx)
        list_for_each_entry_safe(ctx, back, &spoe_appctx->waiting_queue, list) {
                LIST_DEL(&ctx->list);
                LIST_INIT(&ctx->list);
+               HA_ATOMIC_SUB(&agent->counters.nb_waiting, 1);
                spoe_update_stat_time(&ctx->stats.tv_wait, &ctx->stats.t_waiting);
                ctx->state = SPOE_CTX_ST_ERROR;
                ctx->status_code = (spoe_appctx->status_code + 0x100);
@@ -1294,6 +1297,7 @@ spoe_release_appctx(struct appctx *appctx)
        list_for_each_entry_safe(ctx, back, &agent->rt[tid].sending_queue, list) {
                LIST_DEL(&ctx->list);
                LIST_INIT(&ctx->list);
+               HA_ATOMIC_SUB(&agent->counters.nb_sending, 1);
                spoe_update_stat_time(&ctx->stats.tv_queue, &ctx->stats.t_queue);
                ctx->state = SPOE_CTX_ST_ERROR;
                ctx->status_code = (spoe_appctx->status_code + 0x100);
@@ -1302,6 +1306,7 @@ spoe_release_appctx(struct appctx *appctx)
        list_for_each_entry_safe(ctx, back, &agent->rt[tid].waiting_queue, list) {
                LIST_DEL(&ctx->list);
                LIST_INIT(&ctx->list);
+               HA_ATOMIC_SUB(&agent->counters.nb_waiting, 1);
                spoe_update_stat_time(&ctx->stats.tv_wait, &ctx->stats.t_waiting);
                ctx->state = SPOE_CTX_ST_ERROR;
                ctx->status_code = (spoe_appctx->status_code + 0x100);
@@ -1426,6 +1431,7 @@ spoe_handle_connecting_appctx(struct appctx *appctx)
                        /* HELLO handshake is finished, set the idle timeout and
                         * add the applet in the list of running applets. */
                        SPOE_DEBUG_STMT(agent->rt[tid].applets_idle++);
+                       HA_ATOMIC_ADD(&agent->counters.idles, 1);
                        appctx->st0 = SPOE_APPCTX_ST_IDLE;
                        SPOE_APPCTX(appctx)->node.key = 0;
                        eb32_insert(&agent->rt[tid].idle_applets, &SPOE_APPCTX(appctx)->node);
@@ -1495,6 +1501,7 @@ spoe_handle_sending_frame_appctx(struct appctx *appctx, int *skip)
                        spoe_release_buffer(&ctx->buffer, &ctx->buffer_wait);
                        LIST_DEL(&ctx->list);
                        LIST_INIT(&ctx->list);
+                       HA_ATOMIC_SUB(&agent->counters.nb_sending, 1);
                        spoe_update_stat_time(&ctx->stats.tv_queue, &ctx->stats.t_queue);
                        ctx->spoe_appctx = NULL;
                        ctx->state = SPOE_CTX_ST_ERROR;
@@ -1514,6 +1521,7 @@ spoe_handle_sending_frame_appctx(struct appctx *appctx, int *skip)
                        spoe_release_buffer(&ctx->buffer, &ctx->buffer_wait);
                        LIST_DEL(&ctx->list);
                        LIST_INIT(&ctx->list);
+                       HA_ATOMIC_SUB(&agent->counters.nb_sending, 1);
                        spoe_update_stat_time(&ctx->stats.tv_queue, &ctx->stats.t_queue);
                        ctx->spoe_appctx = SPOE_APPCTX(appctx);
                        if (!(ctx->flags & SPOE_CTX_FL_FRAGMENTED) ||
@@ -1548,6 +1556,7 @@ spoe_handle_sending_frame_appctx(struct appctx *appctx, int *skip)
                *skip = 1;
                LIST_ADDQ(&SPOE_APPCTX(appctx)->waiting_queue, &ctx->list);
        }
+       HA_ATOMIC_ADD(&agent->counters.nb_waiting, 1);
        ctx->stats.tv_wait = now;
        SPOE_APPCTX(appctx)->frag_ctx.ctx    = NULL;
        SPOE_APPCTX(appctx)->frag_ctx.cursid = 0;
@@ -1571,6 +1580,7 @@ spoe_handle_sending_frame_appctx(struct appctx *appctx, int *skip)
 static int
 spoe_handle_receiving_frame_appctx(struct appctx *appctx, int *skip)
 {
+       struct spoe_agent   *agent = SPOE_APPCTX(appctx)->agent;
        struct spoe_context *ctx = NULL;
        char *frame;
        int   ret;
@@ -1602,6 +1612,7 @@ spoe_handle_receiving_frame_appctx(struct appctx *appctx, int *skip)
                default:
                        LIST_DEL(&ctx->list);
                        LIST_INIT(&ctx->list);
+                       HA_ATOMIC_SUB(&agent->counters.nb_waiting, 1);
                        spoe_update_stat_time(&ctx->stats.tv_wait, &ctx->stats.t_waiting);
                        ctx->stats.tv_response = now;
                        if (ctx->spoe_appctx) {
@@ -1708,6 +1719,7 @@ spoe_handle_processing_appctx(struct appctx *appctx)
 
        if (appctx->st0 == SPOE_APPCTX_ST_PROCESSING && SPOE_APPCTX(appctx)->cur_fpa < agent->max_fpa) {
                SPOE_DEBUG_STMT(agent->rt[tid].applets_idle++);
+               HA_ATOMIC_ADD(&agent->counters.idles, 1);
                appctx->st0 = SPOE_APPCTX_ST_IDLE;
                eb32_insert(&agent->rt[tid].idle_applets, &SPOE_APPCTX(appctx)->node);
        }
@@ -1871,6 +1883,7 @@ spoe_handle_appctx(struct appctx *appctx)
 
                case SPOE_APPCTX_ST_IDLE:
                        SPOE_DEBUG_STMT(agent->rt[tid].applets_idle--);
+                       HA_ATOMIC_SUB(&agent->counters.idles, 1);
                        eb32_delete(&SPOE_APPCTX(appctx)->node);
                        if (stopping &&
                            LIST_ISEMPTY(&agent->rt[tid].sending_queue) &&
@@ -1988,6 +2001,7 @@ spoe_create_appctx(struct spoe_config *conf)
        LIST_ADDQ(&conf->agent->rt[tid].applets, &SPOE_APPCTX(appctx)->list);
        HA_SPIN_UNLOCK(SPOE_APPLET_LOCK, &conf->agent->rt[tid].lock);
        SPOE_DEBUG_STMT(conf->agent->rt[tid].applets_act++);
+       HA_ATOMIC_ADD(&conf->agent->counters.applets, 1);
 
        task_wakeup(SPOE_APPCTX(appctx)->task, TASK_WOKEN_INIT);
        task_wakeup(strm->task, TASK_WOKEN_INIT);
@@ -2072,6 +2086,7 @@ spoe_queue_context(struct spoe_context *ctx)
 
        /* Add the SPOE context in the sending queue */
        LIST_ADDQ(&agent->rt[tid].sending_queue, &ctx->list);
+       HA_ATOMIC_ADD(&agent->counters.nb_sending, 1);
        spoe_update_stat_time(&ctx->stats.tv_request, &ctx->stats.t_request);
        ctx->stats.tv_queue = now;
 
@@ -2459,6 +2474,68 @@ spoe_process_actions(struct stream *s, struct spoe_context *ctx, int dir)
 /***************************************************************************
  * Functions that process SPOE events
  **************************************************************************/
+static void
+spoe_update_stats(struct stream *s, struct spoe_agent *agent,
+                 struct spoe_context *ctx, int dir)
+{
+       if (!tv_iszero(&ctx->stats.tv_start)) {
+               spoe_update_stat_time(&ctx->stats.tv_start, &ctx->stats.t_process);
+               ctx->stats.t_total  += ctx->stats.t_process;
+               tv_zero(&ctx->stats.tv_request);
+               tv_zero(&ctx->stats.tv_queue);
+               tv_zero(&ctx->stats.tv_wait);
+               tv_zero(&ctx->stats.tv_response);
+       }
+
+       if (agent->var_t_process) {
+               struct sample smp;
+
+               memset(&smp, 0, sizeof(smp));
+               smp_set_owner(&smp, s->be, s->sess, s, dir|SMP_OPT_FINAL);
+               smp.data.u.sint = ctx->stats.t_process;
+               smp.data.type   = SMP_T_SINT;
+
+               spoe_set_var(ctx, "txn", agent->var_t_process,
+                            strlen(agent->var_t_process), &smp);
+       }
+
+       if (agent->var_t_total) {
+               struct sample smp;
+
+               memset(&smp, 0, sizeof(smp));
+               smp_set_owner(&smp, s->be, s->sess, s, dir|SMP_OPT_FINAL);
+               smp.data.u.sint = ctx->stats.t_total;
+               smp.data.type   = SMP_T_SINT;
+
+               spoe_set_var(ctx, "txn", agent->var_t_total,
+                            strlen(agent->var_t_total), &smp);
+       }
+}
+
+static void
+spoe_handle_processing_error(struct stream *s, struct spoe_agent *agent,
+                            struct spoe_context *ctx, int dir)
+{
+       if (agent->eps_max > 0)
+               update_freq_ctr(&agent->rt[tid].err_per_sec, 1);
+
+       if (agent->var_on_error) {
+               struct sample smp;
+
+               memset(&smp, 0, sizeof(smp));
+               smp_set_owner(&smp, s->be, s->sess, s, dir|SMP_OPT_FINAL);
+               smp.data.u.sint = ctx->status_code;
+               smp.data.type   = SMP_T_BOOL;
+
+               spoe_set_var(ctx, "txn", agent->var_on_error,
+                            strlen(agent->var_on_error), &smp);
+       }
+
+       ctx->state = ((agent->flags & SPOE_FL_CONT_ON_ERR)
+                     ? SPOE_CTX_ST_READY
+                     : SPOE_CTX_ST_NONE);
+}
+
 static inline int
 spoe_start_processing(struct spoe_agent *agent, struct spoe_context *ctx, int dir)
 {
@@ -2493,7 +2570,7 @@ spoe_stop_processing(struct spoe_agent *agent, struct spoe_context *ctx)
 
        if (!(ctx->flags & SPOE_CTX_FL_PROCESS))
                return;
-
+       HA_ATOMIC_ADD(&agent->counters.nb_processed, 1);
        if (sa) {
                if (sa->frag_ctx.ctx == ctx) {
                        sa->frag_ctx.ctx = NULL;
@@ -2519,73 +2596,16 @@ spoe_stop_processing(struct spoe_agent *agent, struct spoe_context *ctx)
        ctx->frag_ctx.flags       = 0;
 
        if (!LIST_ISEMPTY(&ctx->list)) {
+               if (ctx->state == SPOE_CTX_ST_SENDING_MSGS)
+                       HA_ATOMIC_ADD(&agent->counters.nb_sending, 1);
+               else
+                       HA_ATOMIC_SUB(&agent->counters.nb_waiting, 1);
+
                LIST_DEL(&ctx->list);
                LIST_INIT(&ctx->list);
        }
 }
 
-static void
-spoe_update_stats(struct stream *s, struct spoe_agent *agent,
-                 struct spoe_context *ctx, int dir)
-{
-       if (!tv_iszero(&ctx->stats.tv_start)) {
-               spoe_update_stat_time(&ctx->stats.tv_start, &ctx->stats.t_process);
-               ctx->stats.t_total  += ctx->stats.t_process;
-               tv_zero(&ctx->stats.tv_request);
-               tv_zero(&ctx->stats.tv_queue);
-               tv_zero(&ctx->stats.tv_wait);
-               tv_zero(&ctx->stats.tv_response);
-       }
-
-       if (agent->var_t_process) {
-               struct sample smp;
-
-               memset(&smp, 0, sizeof(smp));
-               smp_set_owner(&smp, s->be, s->sess, s, dir|SMP_OPT_FINAL);
-               smp.data.u.sint = ctx->stats.t_process;
-               smp.data.type   = SMP_T_SINT;
-
-               spoe_set_var(ctx, "txn", agent->var_t_process,
-                            strlen(agent->var_t_process), &smp);
-       }
-
-       if (agent->var_t_total) {
-               struct sample smp;
-
-               memset(&smp, 0, sizeof(smp));
-               smp_set_owner(&smp, s->be, s->sess, s, dir|SMP_OPT_FINAL);
-               smp.data.u.sint = ctx->stats.t_total;
-               smp.data.type   = SMP_T_SINT;
-
-               spoe_set_var(ctx, "txn", agent->var_t_total,
-                            strlen(agent->var_t_total), &smp);
-       }
-}
-
-static void
-spoe_handle_processing_error(struct stream *s, struct spoe_agent *agent,
-                            struct spoe_context *ctx, int dir)
-{
-       if (agent->eps_max > 0)
-               update_freq_ctr(&agent->rt[tid].err_per_sec, 1);
-
-       if (agent->var_on_error) {
-               struct sample smp;
-
-               memset(&smp, 0, sizeof(smp));
-               smp_set_owner(&smp, s->be, s->sess, s, dir|SMP_OPT_FINAL);
-               smp.data.u.sint = ctx->status_code;
-               smp.data.type   = SMP_T_BOOL;
-
-               spoe_set_var(ctx, "txn", agent->var_on_error,
-                            strlen(agent->var_on_error), &smp);
-       }
-
-       ctx->state = ((agent->flags & SPOE_FL_CONT_ON_ERR)
-                     ? SPOE_CTX_ST_READY
-                     : SPOE_CTX_ST_NONE);
-}
-
 /* Process a list of SPOE messages. First, this functions will process messages
  *  and send them to an agent in a NOTIFY frame. Then, it will wait a ACK frame
  *  to process corresponding actions. During all the processing, it returns 0
@@ -2600,7 +2620,7 @@ spoe_process_messages(struct stream *s, struct spoe_context *ctx,
        int                 ret = 1;
 
        if (ctx->state == SPOE_CTX_ST_ERROR)
-               goto error;
+               goto end;
 
        if (tick_is_expired(ctx->process_exp, now_ms) && ctx->state != SPOE_CTX_ST_DONE) {
                SPOE_PRINTF(stderr, "%d.%06d [SPOE/%-15s] %s: stream=%p"
@@ -2608,7 +2628,7 @@ spoe_process_messages(struct stream *s, struct spoe_context *ctx,
                            (int)now.tv_sec, (int)now.tv_usec,
                            agent->id, __FUNCTION__, s);
                ctx->status_code = SPOE_CTX_ERR_TOUT;
-               goto error;
+               goto end;
        }
 
        if (ctx->state == SPOE_CTX_ST_READY) {
@@ -2642,11 +2662,11 @@ spoe_process_messages(struct stream *s, struct spoe_context *ctx,
                        goto out;
                ret = spoe_encode_messages(s, ctx, messages, dir, type);
                if (ret < 0)
-                       goto error;
+                       goto end;
                if (!ret)
                        goto skip;
                if (spoe_queue_context(ctx) < 0)
-                       goto error;
+                       goto end;
                ctx->state = SPOE_CTX_ST_SENDING_MSGS;
        }
 
@@ -2674,19 +2694,20 @@ spoe_process_messages(struct stream *s, struct spoe_context *ctx,
   out:
        return ret;
 
-  error:
-       spoe_handle_processing_error(s, agent, ctx, dir);
-       ret = 1;
-       goto end;
-
   skip:
        tv_zero(&ctx->stats.tv_start);
        ctx->state = SPOE_CTX_ST_READY;
-       ret = 1;
+       spoe_stop_processing(agent, ctx);
+       return 1;
 
   end:
        spoe_update_stats(s, agent, ctx, dir);
        spoe_stop_processing(agent, ctx);
+       if (ctx->status_code) {
+               HA_ATOMIC_ADD(&agent->counters.nb_errors, 1);
+               spoe_handle_processing_error(s, agent, ctx, dir);
+               ret = 1;
+       }
        return ret;
 }
 
@@ -2712,16 +2733,24 @@ spoe_process_group(struct stream *s, struct spoe_context *ctx,
        ret = spoe_process_messages(s, ctx, &group->messages, dir, SPOE_MSGS_BY_GROUP);
        if (ret && ctx->stats.t_process != -1) {
                SPOE_PRINTF(stderr, "%d.%06d [SPOE/%-15s] %s: stream=%p"
-                           " - <GROUP:%s> sid=%u st=%u %ld/%ld/%ld/%ld/%ld\n",
+                           " - <GROUP:%s> sid=%u st=%u %ld/%ld/%ld/%ld/%ld %u/%u %u/%u %llu/%llu %u/%u\n",
                            (int)now.tv_sec, (int)now.tv_usec, agent->id,
-                           __FUNCTION__, s, s->uniq_id, ctx->status_code,
+                           __FUNCTION__, s, group->id, s->uniq_id, ctx->status_code,
                            ctx->stats.t_request, ctx->stats.t_queue, ctx->stats.t_waiting,
-                           ctx->stats.t_response, ctx->stats.t_process);
-               send_log(&conf->agent_fe, (!ctx->status_code ? LOG_NOTICE : LOG_WARNING),
-                        "SPOE: [%s] <GROUP:%s> sid=%u st=%u %ld/%ld/%ld/%ld/%ld\n",
-                        agent->id, group->id, s->uniq_id, ctx->status_code,
-                        ctx->stats.t_request, ctx->stats.t_queue, ctx->stats.t_waiting,
-                        ctx->stats.t_response, ctx->stats.t_process);
+                           ctx->stats.t_response, ctx->stats.t_process,
+                           agent->counters.idles, agent->counters.applets,
+                           agent->counters.nb_sending, agent->counters.nb_waiting,
+                           agent->counters.nb_errors, agent->counters.nb_processed,
+                           agent->rt[tid].processing, read_freq_ctr(&agent->rt[tid].processing_per_sec));
+               if (ctx->status_code || !(conf->agent_fe.options2 & PR_O2_NOLOGNORM))
+                       send_log(&conf->agent_fe, (!ctx->status_code ? LOG_NOTICE : LOG_WARNING),
+                                "SPOE: [%s] <GROUP:%s> sid=%u st=%u %ld/%ld/%ld/%ld/%ld %u/%u %u/%u %llu/%llu\n",
+                                agent->id, group->id, s->uniq_id, ctx->status_code,
+                                ctx->stats.t_request, ctx->stats.t_queue, ctx->stats.t_waiting,
+                                ctx->stats.t_response, ctx->stats.t_process,
+                                agent->counters.idles, agent->counters.applets,
+                                agent->counters.nb_sending, agent->counters.nb_waiting,
+                                agent->counters.nb_errors, agent->counters.nb_processed);
        }
        return ret;
 }
@@ -2750,16 +2779,24 @@ spoe_process_event(struct stream *s, struct spoe_context *ctx,
        ret = spoe_process_messages(s, ctx, &(ctx->events[ev]), dir, SPOE_MSGS_BY_EVENT);
        if (ret && ctx->stats.t_process != -1) {
                SPOE_PRINTF(stderr, "%d.%06d [SPOE/%-15s] %s: stream=%p"
-                           " - <EVENT:%s> sid=%u st=%u %ld/%ld/%ld/%ld/%ld\n",
+                           " - <EVENT:%s> sid=%u st=%u %ld/%ld/%ld/%ld/%ld %u/%u %u/%u %llu/%llu %u/%u\n",
                            (int)now.tv_sec, (int)now.tv_usec, agent->id,
                            __FUNCTION__, s, spoe_event_str[ev], s->uniq_id, ctx->status_code,
                            ctx->stats.t_request, ctx->stats.t_queue, ctx->stats.t_waiting,
-                           ctx->stats.t_response, ctx->stats.t_process);
-               send_log(&conf->agent_fe, (!ctx->status_code ? LOG_NOTICE : LOG_WARNING),
-                        "SPOE: [%s] <EVENT:%s> sid=%u st=%u %ld/%ld/%ld/%ld/%ld\n",
-                        agent->id, spoe_event_str[ev], s->uniq_id, ctx->status_code,
-                        ctx->stats.t_request, ctx->stats.t_queue, ctx->stats.t_waiting,
-                        ctx->stats.t_response, ctx->stats.t_process);
+                           ctx->stats.t_response, ctx->stats.t_process,
+                           agent->counters.idles, agent->counters.applets,
+                           agent->counters.nb_sending, agent->counters.nb_waiting,
+                           agent->counters.nb_errors, agent->counters.nb_processed,
+                           agent->rt[tid].processing, read_freq_ctr(&agent->rt[tid].processing_per_sec));
+               if (ctx->status_code || !(conf->agent_fe.options2 & PR_O2_NOLOGNORM))
+                       send_log(&conf->agent_fe, (!ctx->status_code ? LOG_NOTICE : LOG_WARNING),
+                                "SPOE: [%s] <EVENT:%s> sid=%u st=%u %ld/%ld/%ld/%ld/%ld %u/%u %u/%u %llu/%llu\n",
+                                agent->id, spoe_event_str[ev], s->uniq_id, ctx->status_code,
+                                ctx->stats.t_request, ctx->stats.t_queue, ctx->stats.t_waiting,
+                                ctx->stats.t_response, ctx->stats.t_process,
+                                agent->counters.idles, agent->counters.applets,
+                                agent->counters.nb_sending, agent->counters.nb_waiting,
+                                agent->counters.nb_errors, agent->counters.nb_processed);
        }
        return ret;
 }
@@ -4451,8 +4488,8 @@ spoe_send_group(struct act_rule *rule, struct proxy *px,
                                    (int)now.tv_sec, (int)now.tv_usec,
                                    agent->id, __FUNCTION__, s, group->id);
                        ctx->status_code = SPOE_CTX_ERR_INTERRUPT;
-                       spoe_handle_processing_error(s, agent, ctx, dir);
                        spoe_stop_processing(agent, ctx);
+                       spoe_handle_processing_error(s, agent, ctx, dir);
                        return ACT_RET_CONT;
                }
                return ACT_RET_YIELD;