Subversion Repositories SmartDukaan

Rev

Rev 37472 | Show entire file | Ignore whitespace | Details | Blame | Last modification | View Log | RSS feed

Rev 37472 Rev 37565
Line 1... Line 1...
1
package com.smartdukaan.cron.monitored;
1
package com.smartdukaan.cron.monitored;
2
 
2
 
-
 
3
import java.time.LocalDate;
3
import java.util.Map;
4
import java.util.Map;
4
import java.util.concurrent.ConcurrentHashMap;
5
import java.util.concurrent.ConcurrentHashMap;
5
import java.util.concurrent.atomic.AtomicInteger;
6
import java.util.concurrent.atomic.AtomicInteger;
6
import java.util.concurrent.atomic.AtomicLong;
7
import java.util.concurrent.atomic.AtomicLong;
7
 
8
 
Line 38... Line 39...
38
 *                 number, not a health one. Do not alert on it alone.
39
 *                 number, not a health one. Do not alert on it alone.
39
 *
40
 *
40
 * Rates are deliberately NOT published. solved/shown and dates/answered are one division
41
 * Rates are deliberately NOT published. solved/shown and dates/answered are one division
41
 * in PromQL and storing them would freeze the numerator and denominator apart.
42
 * in PromQL and storing them would freeze the numerator and denominator apart.
42
 *
43
 *
43
 * -1 means "no pass has finished since this JVM started", so a scrape before the first
44
 * -1 means "no day has been cleared since this JVM started", so a scrape before the first
44
 * run is distinguishable from a genuine zero -- same convention as {@link BalanceGauges}.
45
 * tick is distinguishable from a genuine zero -- same convention as {@link BalanceGauges}.
-
 
46
 *
-
 
47
 * ⚠ The gauges are registered lazily, on the first tick that names a brand. After a
-
 
48
 * restart the whole imei_activation_* family is therefore ABSENT from /actuator/prometheus
-
 
49
 * rather than reading -1, until each lane takes its first turn. Under the old midnight
-
 
50
 * cron that blind window could last most of a day; under a 20-second tick it is seconds.
45
 */
51
 */
46
@Component
52
@Component
47
public class ImeiActivationGauges {
53
public class ImeiActivationGauges {
48
 
54
 
49
    private static final Logger LOGGER = LogManager.getLogger(ImeiActivationGauges.class);
55
    private static final Logger LOGGER = LogManager.getLogger(ImeiActivationGauges.class);
Line 55... Line 61...
55
 
61
 
56
    public ImeiActivationGauges(MeterRegistry meterRegistry) {
62
    public ImeiActivationGauges(MeterRegistry meterRegistry) {
57
        this.meterRegistry = meterRegistry;
63
        this.meterRegistry = meterRegistry;
58
    }
64
    }
59
 
65
 
-
 
66
    /**
-
 
67
     * True while this brand has not yet opened today's funnel.
-
 
68
     *
-
 
69
     * The caller uses it to decide how much pool to fetch: on the day's first tick it
-
 
70
     * needs the whole thing to have a denominator, on every later tick it needs only the
-
 
71
     * next chunk. Asking here keeps that decision in one place rather than duplicating a
-
 
72
     * date field per lane.
-
 
73
     */
-
 
74
    public boolean needsDayStart(String brand) {
-
 
75
        return !LocalDate.now().equals(funnel(brand).day);
-
 
76
    }
-
 
77
 
-
 
78
    /**
-
 
79
     * Open a brand's funnel for today, with the pool size measured on the first tick.
-
 
80
     *
-
 
81
     * The unit used to be a pass -- one bounded run that began and ended inside a single
60
    /** Called once at the start of a brand's daily pass, with the snapshotted pool size. */
82
     * call. Ticks have no such boundary, so the DAY is the unit now: `due` is what was
-
 
83
     * outstanding at the first tick after midnight, and everything else accumulates
-
 
84
     * across the day's ticks until the pool comes back empty.
-
 
85
     *
-
 
86
     * Truncation is detected HERE rather than at the end of a run, because a day that
-
 
87
     * ran out of hours never reaches endDay at all -- it just stops. Rolling over with
-
 
88
     * yesterday still open is exactly that case, and it is the line worth alerting on.
-
 
89
     */
61
    public void beginPass(String brand, int due) {
90
    public void beginDay(String brand, int due) {
62
        BrandFunnel f = funnel(brand);
91
        BrandFunnel f = funnel(brand);
-
 
92
        if (f.day != null && !f.finished) {
-
 
93
            LOGGER.warn("[{}] {} ended without clearing: {} of {} imeis churned, the tail rolls into today",
-
 
94
                    brand, f.day, f.churned.get(), f.due.get());
-
 
95
        }
63
        f.reset(due);
96
        f.reset(due);
-
 
97
        f.day = LocalDate.now();
-
 
98
        f.finished = false;
64
        LOGGER.info("[{}] pass begin: {} imeis due", brand, due);
99
        LOGGER.info("[{}] day begin: {} imeis due", brand, due);
65
    }
100
    }
66
 
101
 
67
    /** A captcha widget rendered and is ready to be attacked. */
102
    /** A captcha widget rendered and is ready to be attacked. */
68
    public void captchaShown(String brand) {
103
    public void captchaShown(String brand) {
69
        funnel(brand).captchaShown.incrementAndGet();
104
        funnel(brand).captchaShown.incrementAndGet();
Line 96... Line 131...
96
    public void error(String brand) {
131
    public void error(String brand) {
97
        funnel(brand).errors.incrementAndGet();
132
        funnel(brand).errors.incrementAndGet();
98
    }
133
    }
99
 
134
 
100
    /**
135
    /**
-
 
136
     * Called the first time a brand's turn comes back with nothing due, which under a
101
     * Called once when a brand's pass ends. Stamps the duration and the completion time,
137
     * tick model is what "the day's work is cleared" means. Stamps the duration and the
102
     * and logs the one line worth grepping for.
138
     * completion time, and logs the one line worth grepping for.
-
 
139
     *
-
 
140
     * Idempotent by design: every later tick that day also finds an empty pool and calls
-
 
141
     * this, and must stay silent. Silence is the point -- at a 20-second cadence a log
-
 
142
     * line per idle tick is 4,320 lines a day per brand on a log that is already 1.8GB.
-
 
143
     *
-
 
144
     * lastFinishEpoch therefore becomes a genuine completion clock. It read -1 for three
-
 
145
     * days straight under the old model, which said only "no pass has finished since this
-
 
146
     * JVM started" and could not distinguish a truncated pass from a fresh restart.
103
     */
147
     */
104
    public void endPass(String brand) {
148
    public void endDay(String brand) {
105
        BrandFunnel f = funnel(brand);
149
        BrandFunnel f = funnel(brand);
-
 
150
        if (!LocalDate.now().equals(f.day) || f.finished) {
-
 
151
            return;
-
 
152
        }
-
 
153
        f.finished = true;
106
        long seconds = (System.currentTimeMillis() - f.startedAtMillis) / 1000;
154
        long seconds = (System.currentTimeMillis() - f.startedAtMillis) / 1000;
107
        f.runSeconds.set(seconds);
155
        f.runSeconds.set(seconds);
108
        f.lastFinishEpoch.set(System.currentTimeMillis() / 1000);
156
        f.lastFinishEpoch.set(System.currentTimeMillis() / 1000);
109
 
157
 
110
        int shown = f.captchaShown.get();
158
        int shown = f.captchaShown.get();
111
        int solved = f.captchaSolved.get();
159
        int solved = f.captchaSolved.get();
112
        int answered = f.answered.get();
160
        int answered = f.answered.get();
113
        LOGGER.info("[{}] pass end: due={} churned={} captcha {}/{} ({}%) answered={} dates={} errors={} in {}s",
161
        LOGGER.info("[{}] day cleared: due={} churned={} captcha {}/{} ({}%) answered={} dates={} errors={} in {}s",
114
                brand, f.due.get(), f.churned.get(), solved, shown, percent(solved, shown),
162
                brand, f.due.get(), f.churned.get(), solved, shown, percent(solved, shown),
115
                answered, f.datesFound.get(), f.errors.get(), seconds);
163
                answered, f.datesFound.get(), f.errors.get(), seconds);
116
 
164
 
117
        if (f.churned.get() > 0 && answered == 0) {
165
        if (f.churned.get() > 0 && answered == 0) {
118
            LOGGER.error("[{}] pass answered NOTHING across {} imeis -- the brand is down, not merely unlucky",
166
            LOGGER.error("[{}] answered NOTHING across {} imeis -- the brand is down, not merely unlucky",
119
                    brand, f.churned.get());
167
                    brand, f.churned.get());
120
        }
168
        }
121
        if (f.churned.get() < f.due.get()) {
169
        // churned short of due is normal now rather than a truncation: the pool is
-
 
170
        // re-queried every tick, so anything another writer filled in mid-day (carlcare
122
            LOGGER.warn("[{}] pass did not finish: {} of {} imeis churned, the tail rolls into tomorrow",
171
        // and the DCR pull both write rows) leaves without this lane ever touching it.
123
                    brand, f.churned.get(), f.due.get());
172
        // Real truncation is the day that never gets here at all, caught in beginDay.
124
        }
-
 
125
    }
173
    }
126
 
174
 
127
    private static int percent(int part, int whole) {
175
    private static int percent(int part, int whole) {
128
        return whole == 0 ? 0 : (int) Math.round(100.0 * part / whole);
176
        return whole == 0 ? 0 : (int) Math.round(100.0 * part / whole);
129
    }
177
    }
Line 132... Line 180...
132
        return byBrand.computeIfAbsent(brand, b -> new BrandFunnel(meterRegistry, b));
180
        return byBrand.computeIfAbsent(brand, b -> new BrandFunnel(meterRegistry, b));
133
    }
181
    }
134
 
182
 
135
    /**
183
    /**
136
     * One brand's counters, registered against the meter registry the first time that
184
     * One brand's counters, registered against the meter registry the first time that
137
     * brand is seen. Gauges hold last-pass values rather than lifetime totals: these
185
     * brand is seen. Gauges hold the CURRENT DAY's values rather than lifetime totals:
138
     * passes run once a day, so "what did the last run do" is the question being asked,
186
     * the question being asked is "how far has today got", and a lifetime counter cannot
139
     * and a counter that only moves once a day is awkward to alert on.
187
     * answer it. They climb across the day's ticks and reset at the first tick after
-
 
188
     * midnight.
140
     */
189
     */
141
    private static final class BrandFunnel {
190
    private static final class BrandFunnel {
142
 
191
 
143
        private final AtomicInteger due = new AtomicInteger(NOT_RUN_YET);
192
        private final AtomicInteger due = new AtomicInteger(NOT_RUN_YET);
144
        private final AtomicInteger churned = new AtomicInteger(NOT_RUN_YET);
193
        private final AtomicInteger churned = new AtomicInteger(NOT_RUN_YET);
Line 150... Line 199...
150
        private final AtomicLong runSeconds = new AtomicLong(NOT_RUN_YET);
199
        private final AtomicLong runSeconds = new AtomicLong(NOT_RUN_YET);
151
        private final AtomicLong lastFinishEpoch = new AtomicLong(NOT_RUN_YET);
200
        private final AtomicLong lastFinishEpoch = new AtomicLong(NOT_RUN_YET);
152
 
201
 
153
        private volatile long startedAtMillis = System.currentTimeMillis();
202
        private volatile long startedAtMillis = System.currentTimeMillis();
154
 
203
 
-
 
204
        /** The day this funnel is currently accumulating; null until the first tick ever. */
-
 
205
        private volatile LocalDate day;
-
 
206
 
-
 
207
        /** Whether that day's pool has already come back empty. Keeps endDay silent after the first. */
-
 
208
        private volatile boolean finished;
-
 
209
 
155
        BrandFunnel(MeterRegistry registry, String brand) {
210
        BrandFunnel(MeterRegistry registry, String brand) {
156
            Tags tags = Tags.of("brand", brand.toLowerCase());
211
            Tags tags = Tags.of("brand", brand.toLowerCase());
157
            gauge(registry, "imei_activation_due", tags, due,
212
            gauge(registry, "imei_activation_due", tags, due,
158
                    "Imeis the last pass snapshotted for this brand; -1 = no pass yet");
213
                    "Imeis outstanding at the first tick after midnight; -1 = no tick yet");
159
            gauge(registry, "imei_activation_churned", tags, churned,
214
            gauge(registry, "imei_activation_churned", tags, churned,
160
                    "Imeis the last pass actually reached; short of due means it ran out of day");
215
                    "Imeis today's ticks have reached so far; catches up to due when the day clears");
161
            gauge(registry, "imei_activation_captcha_shown", tags, captchaShown,
216
            gauge(registry, "imei_activation_captcha_shown", tags, captchaShown,
162
                    "Captchas that rendered; collapses when the far end stops serving the widget");
217
                    "Captchas that rendered; collapses when the far end stops serving the widget");
163
            gauge(registry, "imei_activation_captcha_solved", tags, captchaSolved,
218
            gauge(registry, "imei_activation_captcha_solved", tags, captchaSolved,
164
                    "Captchas broken; divide by captcha_shown for the solver's accuracy");
219
                    "Captchas broken; divide by captcha_shown for the solver's accuracy");
165
            gauge(registry, "imei_activation_answered", tags, answered,
220
            gauge(registry, "imei_activation_answered", tags, answered,