Line data Source code
1 : #ifndef HEADER_fd_src_flamenco_log_collector_fd_log_collector_h
2 : #define HEADER_fd_src_flamenco_log_collector_fd_log_collector_h
3 :
4 : #include "fd_log_collector_base.h"
5 : #include "../runtime/context/fd_exec_instr_ctx.h"
6 : #include "../runtime/context/fd_exec_txn_ctx.h"
7 : #include "../../ballet/base58/fd_base58.h"
8 : #include "../../ballet/base64/fd_base64.h"
9 : #include <stdio.h>
10 : #include <stdarg.h>
11 :
12 : /* Log collector + stable log implementations.
13 : https://github.com/anza-xyz/agave/blob/v2.0.6/program-runtime/src/log_collector.rs
14 : https://github.com/anza-xyz/agave/blob/v2.0.6/program-runtime/src/stable_log.rs */
15 :
16 : /* INTERNALS
17 : Internal functions, don't use directly. */
18 :
19 5784 : #define FD_EXEC_LITERAL(STR) ("" STR), (sizeof(STR)-1)
20 :
21 : /* fd_log_collector_private_push pushes a log (internal, don't use directly).
22 :
23 : This function stores a log msg of size msg_sz, serialized as protobuf.
24 : For the high-level functionality, see fd_log_collector_msg().
25 :
26 : Internally, each log msg is serialized as a 1 byte tag + 1 or 2 bytes
27 : msg_sz (variable int < 32768) + msg_sz bytes of the actual msg.
28 :
29 : | tag | msg_sz | msg |
30 : | 1-byte | 1-or-2 bytes | msg_sz bytes |
31 :
32 : The advantage of this representation is that when we have to store
33 : txn metadata in blockstore, we don't have to do any conversion for logs,
34 : just copy the entire buffer. */
35 : static inline void
36 : fd_log_collector_private_push( fd_log_collector_t * log,
37 : char const * msg,
38 6021 : ulong msg_sz ) {
39 6021 : uchar * buf = log->buf;
40 6021 : ulong buf_sz = log->buf_sz;
41 :
42 : /* Store tag + msg_sz */
43 6021 : ulong needs_2b = (msg_sz>0x7F);
44 6021 : buf[ buf_sz ] = FD_LOG_COLLECTOR_PROTO_TAG;
45 6021 : buf[ buf_sz+1 ] = (uchar)( (msg_sz&0x7F) | (needs_2b<<7) );
46 6021 : buf[ buf_sz+2 ] = (uchar)( (msg_sz>>7) & 0x7F ); /* This gets overwritten if 0 */
47 :
48 : /* Copy msg and update total buf_sz */
49 6021 : ulong msg_start = buf_sz + 2 + needs_2b;
50 6021 : fd_memcpy( buf + msg_start, msg, msg_sz );
51 6021 : log->buf_sz = (ushort)( msg_start + msg_sz );
52 6021 : }
53 :
54 : /* fd_log_collector_private_debug prints all logs (internal, don't use directly). */
55 : static inline void
56 : fd_log_collector_private_debug( fd_log_collector_t const * log );
57 :
58 : FD_PROTOTYPES_BEGIN
59 :
60 : /* LOG COLLECTOR API
61 : Init, delete... */
62 :
63 : /* fd_log_collector_init initializes a log collector. */
64 : static inline void
65 400317 : fd_log_collector_init( fd_log_collector_t * log, int enabled ) {
66 400317 : log->buf_sz = 0;
67 400317 : log->log_sz = 0;
68 400317 : log->warn = 0;
69 400317 : log->disabled = !enabled;
70 400317 : }
71 :
72 : static inline ulong
73 : fd_log_collector_check_and_truncate( fd_log_collector_t * log,
74 135078 : ulong msg_sz ) {
75 135078 : ulong bytes_written = fd_ulong_sat_add( log->log_sz, msg_sz );
76 135078 : int ret = bytes_written >= FD_LOG_COLLECTOR_MAX;
77 135078 : if( FD_UNLIKELY( ret ) ) {
78 18 : if( FD_UNLIKELY( !log->warn ) ) {
79 18 : log->warn = 1;
80 18 : fd_log_collector_private_push( log, FD_EXEC_LITERAL( "Log truncated" ) );
81 18 : }
82 18 : return ULONG_MAX;
83 18 : }
84 135060 : return bytes_written;
85 135078 : }
86 :
87 : /* fd_log_collector_delete deletes a log collector. */
88 : static inline void
89 0 : fd_log_collector_delete( fd_log_collector_t const * log ) {
90 0 : (void)log;
91 : #ifdef VLOG
92 : if( FD_LIKELY( log->disabled ) ) {
93 : return;
94 : }
95 : fd_log_collector_private_debug( log );
96 : #endif
97 0 : }
98 :
99 : /* LOG COLLECTOR MSG API
100 :
101 : Analogous of Agave's ic_msg!():
102 : https://github.com/anza-xyz/agave/blob/v2.0.6/program-runtime/src/log_collector.rs
103 :
104 : - fd_log_collector_msg
105 : - fd_log_collector_msg_literal
106 : - fd_log_collector_msg_many
107 : - fd_log_collector_printf_*
108 : */
109 :
110 : /* fd_log_collector_msg logs msg of size msg_sz.
111 : This is analogous of Agave's ic_msg!() / ic_logger_msg!().
112 :
113 : msg is expected to be a valid utf8 string, it's responsibility
114 : of the caller to enforce that. msg doesn't have to be \0 terminated
115 : and can contain \0 within. Most logs are cstr, base58/64, so
116 : they are utf8. For an example of log from user input, see the
117 : sol_log_() syscall where we use fd_utf8_validate().
118 :
119 : if msg is a cstr, for compatibility with rust, msg_sz is the msg
120 : length (not the size of the buffer), and the final \0 should not
121 : be included in logs. For literals, use fd_log_collector_msg_literal().
122 :
123 : msg_sz==0 is ok, however it's important to understand that log
124 : collector is an interface to developers, not exposed to users.
125 : Users can, for example, log inside BPF programs using msg!(), that
126 : gets translated to the syscall sol_log_(), that in turn appends
127 : a log of the form "Program log: ...". So msg_sz, realistically,
128 : is never 0 nor small. This is important for our implementation,
129 : to keep serialization overhead low.
130 :
131 : When msg is made of multiple disjoing buffers, we should use
132 : fd_log_collector_msg_many(), and implement more variants as
133 : needed. The core idea is very simple: we know the total msg_sz,
134 : we decide if the log needs to be included or truncated, and
135 : if we include the logs we will copy the actual content
136 : from multiple places. This should be the correct and high
137 : performance way to log.
138 :
139 : For ease of development, and because logs in runtime, vm,
140 : syscalls, native programs, etc. are what they are, we also
141 : implemented fd_log_collector_printf_*(). These are
142 : dangerous to use, especially given the way we serialize
143 : logs on-the-fly. Prefer fd_log_collector_msg_* wherever
144 : possible. */
145 : static inline void
146 : fd_log_collector_msg( fd_exec_instr_ctx_t * ctx,
147 : char const * msg,
148 7347 : ulong msg_sz ) {
149 7347 : fd_log_collector_t * log = &ctx->txn_ctx->log_collector;
150 7347 : if( FD_LIKELY( log->disabled ) ) {
151 1344 : return;
152 1344 : }
153 :
154 6003 : ulong bytes_written = fd_log_collector_check_and_truncate( log, msg_sz );
155 6003 : if( FD_LIKELY( bytes_written < ULONG_MAX ) ) {
156 6003 : log->log_sz = (ushort)bytes_written;
157 6003 : fd_log_collector_private_push( log, msg, msg_sz );
158 6003 : }
159 6003 : }
160 :
161 : /* fd_log_collector_msg_literal logs the literal (const cstr) msg,
162 : handling size. See fd_log_collector_msg() for details. */
163 5766 : #define fd_log_collector_msg_literal( ctx, log ) fd_log_collector_msg( ctx, FD_EXEC_LITERAL( log ) )
164 :
165 : /* fd_log_collector_msg_many logs a msg supplied as many
166 : buffers. msg := msg0 | msg1 | ... | msgN
167 :
168 : num_buffers informs the number of (char const * msg, ulong sz) pairs
169 : in the function call.
170 : NOTE: you must explicitly pass in ulong values for sz, either by cast
171 : or with the UL literal. va_args behaves weirdly otherwise */
172 : static inline void
173 55200 : fd_log_collector_msg_many( fd_exec_instr_ctx_t * ctx, int num_buffers, ... ) {
174 55200 : fd_log_collector_t * log = &ctx->txn_ctx->log_collector;
175 55200 : if( FD_LIKELY( log->disabled ) ) {
176 819 : return;
177 819 : }
178 :
179 54381 : va_list args;
180 54381 : va_start( args, num_buffers );
181 :
182 : /* Calculate the total message size and check for overflow */
183 54381 : ulong msg_sz = 0;
184 163143 : for( int i = 0; i < num_buffers; i++ ) {
185 108762 : va_arg( args, char const * );
186 108762 : ulong msg_sz_part = va_arg( args, ulong );
187 108762 : msg_sz = fd_ulong_sat_add( msg_sz, msg_sz_part );
188 108762 : }
189 54381 : va_end( args );
190 54381 : ulong bytes_written = fd_log_collector_check_and_truncate( log, msg_sz );
191 54381 : if( FD_LIKELY( bytes_written < ULONG_MAX ) ) {
192 54372 : log->log_sz = (ushort)bytes_written;
193 :
194 54372 : uchar * buf = log->buf;
195 54372 : ulong buf_sz = log->buf_sz;
196 :
197 : /* Store tag + msg_sz */
198 54372 : ulong needs_2b = (msg_sz>0x7F);
199 54372 : buf[ buf_sz ] = FD_LOG_COLLECTOR_PROTO_TAG;
200 54372 : buf[ buf_sz+1 ] = (uchar)( (msg_sz&0x7F) | (needs_2b<<7) );
201 54372 : buf[ buf_sz+2 ] = (uchar)( (msg_sz>>7) & 0x7F ); /* This gets overwritten if 0 */
202 :
203 : /* Copy all messages and update total buf_sz */
204 54372 : ulong buf_start = buf_sz + 2 + needs_2b;
205 54372 : ulong offset = buf_start;
206 :
207 54372 : va_start(args, num_buffers); // Restart argument list traversal
208 163116 : for (int i = 0; i < num_buffers; i++) {
209 108744 : char const *msg = va_arg( args, char const * );
210 108744 : ulong msg_sz_part = va_arg( args, ulong );
211 108744 : fd_memcpy( buf + offset, msg, msg_sz_part );
212 108744 : offset += msg_sz_part;
213 108744 : }
214 54372 : va_end(args);
215 54372 : log->buf_sz = (ushort)offset;
216 54372 : }
217 54381 : }
218 :
219 74622 : #define FD_LOG_COLLECTOR_PRINTF_MAX_1B 128
220 0 : #define FD_LOG_COLLECTOR_PRINTF_MAX_2B 2000
221 : FD_STATIC_ASSERT( 2*FD_LOG_COLLECTOR_PRINTF_MAX_2B <= FD_LOG_COLLECTOR_EXTRA, "Increase FD_LOG_COLLECTOR_EXTRA" );
222 :
223 : /* fd_log_collector_printf_dangerous_max_127() logs a message
224 : supplied as a formatting string with params.
225 :
226 : This is dangerous and should only be used when we can
227 : guarantee that the total log msg_sz <= 127.
228 :
229 : See also fd_log_collector_printf_dangerous_128_to_2k() for
230 : larger logs, and see fd_log_collector_program_return() for
231 : an example on how to deal with msg_sz.
232 :
233 : This implementation uses vsnprintf() to directly write into
234 : the log buf *before* deciding if the log should be included
235 : or not. As a result of vsnprintf() we get msg_sz, and then
236 : we can decide to actually insert the log or truncate. Since
237 : we serialize msg_sz as a variable int, we must guarantee
238 : that msg_sz <= 127, i.e. fits in 1 byte, otherwise we'd have
239 : to memmove the log msg. */
240 : __attribute__ ((format (printf, 2, 3)))
241 : static inline void
242 : fd_log_collector_printf_dangerous_max_127( fd_exec_instr_ctx_t * ctx,
243 78819 : char const * fmt, ... ) {
244 78819 : fd_log_collector_t * log = &ctx->txn_ctx->log_collector;
245 78819 : if( FD_LIKELY( log->disabled ) ) {
246 4197 : return;
247 4197 : }
248 :
249 74622 : uchar * buf = log->buf;
250 74622 : ulong buf_sz = log->buf_sz;
251 :
252 : /* Store the log at buf_sz+2 (1 byte tag + 1 byte msg_sz), and retrieve
253 : the final msg_sz. */
254 74622 : va_list ap;
255 74622 : va_start( ap, fmt );
256 74622 : int res = vsnprintf( (char *)(buf + buf_sz + 2), FD_LOG_COLLECTOR_PRINTF_MAX_1B, fmt, ap );
257 74622 : va_end( ap );
258 :
259 : /* We use vsnprintf to protect against oob writes, however it should never
260 : truncate. If truncate happens, it means that we're using
261 : fd_log_collector_printf_dangerous_max_127(), incorrectly for example
262 : with a "%s" and an unbound variable (user input, var that's not
263 : null-terminated cstr, ...).
264 : We MUST only use fd_log_collector_printf_dangerous_max_127()
265 : as a convenince method, when we can guarantee that the total msg_sz is
266 : bound by FD_LOG_COLLECTOR_PRINTF_MAX_1B. */
267 74622 : FD_TEST_CUSTOM( res>=0 && res<FD_LOG_COLLECTOR_PRINTF_MAX_1B,
268 74622 : "A transaction log was truncated unexpectedly. Please report to developers." );
269 :
270 : /* Decide if we should include the log or truncate. */
271 74622 : ulong msg_sz = (ulong)res;
272 74622 : ulong bytes_written = fd_log_collector_check_and_truncate( log, msg_sz );
273 74622 : if( FD_LIKELY( bytes_written < ULONG_MAX ) ) {
274 : /* Insert log: store tag + msg_sz (1 byte) and update buf_sz */
275 74622 : log->log_sz = (ushort)bytes_written;
276 74622 : buf[ buf_sz ] = FD_LOG_COLLECTOR_PROTO_TAG;
277 74622 : buf[ buf_sz+1 ] = (uchar)( msg_sz & 0x7F );
278 74622 : log->buf_sz = (ushort)( buf_sz + msg_sz + 2 );
279 74622 : }
280 74622 : }
281 :
282 : /* fd_log_collector_printf_dangerous_128_to_2k() logs a message
283 : supplied as a formatting string with params.
284 :
285 : This is dangerous and should only be used when we can
286 : guarantee that the total log 128 <= msg_sz < 2,000.
287 :
288 : This implementation uses vsnprintf() to directly write into
289 : the log buf *before* deciding if the log should be included
290 : or not. As a result of vsnprintf() we get msg_sz, and then
291 : we can decide to actually insert the log or truncate. Since
292 : we serialize msg_sz as a variable int, we must guarantee
293 : that 128 <= msg_sz < 32758, i.e. fits in 2 byte, otherwise
294 : we'd have to memmove the log msg.
295 :
296 : Moreover, we need to guarantee that the log buf is big enough
297 : to fit the log msg. Hence we further limit msg_sz < 2000. */
298 : __attribute__ ((format (printf, 2, 3)))
299 : static inline void
300 : fd_log_collector_printf_dangerous_128_to_2k( fd_exec_instr_ctx_t * ctx,
301 0 : char const * fmt, ... ) {
302 0 : fd_log_collector_t * log = &ctx->txn_ctx->log_collector;
303 0 : if( FD_LIKELY( log->disabled ) ) {
304 0 : return;
305 0 : }
306 :
307 0 : uchar * buf = log->buf;
308 0 : ulong buf_sz = log->buf_sz;
309 :
310 : /* Store the log at buf_sz+3 (1 byte tag + 2 bytes msg_sz), and retrieve
311 : the final msg_sz. */
312 0 : va_list ap;
313 0 : va_start( ap, fmt );
314 0 : int res = vsnprintf( (char *)(buf + buf_sz + 3), FD_LOG_COLLECTOR_PRINTF_MAX_2B, fmt, ap );
315 0 : va_end( ap );
316 : /* We use vsnprintf to protect against oob writes, however it should never
317 : truncate. If truncate happens, it means that we're using
318 : fd_log_collector_printf_dangerous_max_127(), incorrectly for example
319 : with a "%s" and an unbound variable (user input, var that's not
320 : null-terminated cstr, ...).
321 : We MUST only use fd_log_collector_printf_dangerous_max_127()
322 : as a convenince method, when we can guarantee that the total msg_sz is
323 : bound by FD_LOG_COLLECTOR_PRINTF_MAX_2B. */
324 0 : FD_TEST_CUSTOM( res>=FD_LOG_COLLECTOR_PRINTF_MAX_1B && res<FD_LOG_COLLECTOR_PRINTF_MAX_2B,
325 0 : "A transaction log was truncated unexpectedly. Please report to developers." );
326 :
327 : /* Decide if we should include the log or truncate. */
328 0 : ulong msg_sz = (ulong)res;
329 0 : ulong bytes_written = fd_log_collector_check_and_truncate( log, msg_sz );
330 0 : if( FD_LIKELY( bytes_written < ULONG_MAX ) ) {
331 : /* Insert log: store tag + msg_sz (2 bytes) and update buf_sz */
332 0 : log->log_sz = (ushort)bytes_written;
333 0 : buf[ buf_sz ] = FD_LOG_COLLECTOR_PROTO_TAG;
334 0 : buf[ buf_sz+1 ] = (uchar)( (msg_sz&0x7F) | (1<<7) );
335 0 : buf[ buf_sz+2 ] = (uchar)( (msg_sz>>7) & 0x7F );
336 0 : log->buf_sz = (ushort)( buf_sz + msg_sz + 3 );
337 0 : }
338 0 : }
339 :
340 : /* fd_log_collector_printf_inefficient_max_512() logs a message
341 : supplied as a formatting string with params.
342 :
343 : This is inefficient because it uses an external buffer and
344 : essentially does 2 memcpy instead of 1, however it reduces
345 : the complexity when msg_sz can be below or above 127, for
346 : example in many error messages where we have to print 2
347 : pubkeys. */
348 : __attribute__ ((format (printf, 2, 3)))
349 : static inline void
350 : fd_log_collector_printf_inefficient_max_512( fd_exec_instr_ctx_t * ctx,
351 1518 : char const * fmt, ... ) {
352 1518 : char msg[ 512 ];
353 :
354 1518 : va_list ap;
355 1518 : va_start( ap, fmt );
356 1518 : int msg_sz = vsnprintf( msg, sizeof(msg), fmt, ap );
357 1518 : va_end( ap );
358 :
359 1518 : FD_TEST_CUSTOM( msg_sz>=0 && (ulong)msg_sz<sizeof(msg),
360 1518 : "A transaction log was truncated unexpectedly. Please report to developers." );
361 :
362 1518 : fd_log_collector_msg( ctx, msg, (ulong)msg_sz );
363 1518 : }
364 :
365 : /* STABLE LOG
366 :
367 : Analogous of Agave's stable_log interface:
368 : https://github.com/anza-xyz/agave/blob/v2.0.6/program-runtime/src/stable_log.rs
369 :
370 : - program_invoke
371 : - program_log
372 : - program_data -- implemented in fd_vm_syscall_sol_log_data()
373 : - program_return
374 : - program_success
375 : - program_failure
376 : - program_consumed */
377 :
378 : /* fd_log_collector_program_invoke logs:
379 : "Program <ProgramIdBase58> invoke [<n>]"
380 :
381 : This function is called at the beginning of every instruction.
382 : Other logs (notably success/failure) also write <ProgramIdBase58>,
383 : so this function precomputes it and stores it inside the instr_ctx. */
384 : static inline void
385 68712 : fd_log_collector_program_invoke( fd_exec_instr_ctx_t * ctx ) {
386 68712 : if( FD_LIKELY( ctx->txn_ctx->log_collector.disabled ) ) {
387 6522 : return;
388 6522 : }
389 :
390 : /* Cache ctx->program_id_base58 */
391 62190 : fd_base58_encode_32( ctx->instr->program_id_pubkey.uc, NULL, ctx->program_id_base58 );
392 : /* Max msg_sz: 22 - 4 + 44 + 10 = 72 < 127 => we can use printf */
393 62190 : fd_log_collector_printf_dangerous_max_127( ctx, "Program %s invoke [%u]", ctx->program_id_base58, ctx->depth+1 );
394 62190 : }
395 :
396 : /* fd_log_collector_program_log logs:
397 : "Program <ProgramIdBase58> log: <msg>"
398 :
399 : msg must be a valid utf8 string, it's responsibility of the caller to
400 : validate that. This is the implementation underlying _sol_log() syscall. */
401 : static inline void
402 864 : fd_log_collector_program_log( fd_exec_instr_ctx_t * ctx, char const * msg, ulong msg_sz ) {
403 864 : fd_log_collector_msg_many( ctx, 2, "Program log: ", 13UL, msg, msg_sz );
404 864 : }
405 :
406 : /* fd_log_collector_program_return logs:
407 : "Program return: <ProgramIdBase58> <dataAsBase64>"
408 :
409 : Since return data is at most 1024 bytes, it's base64 representation is
410 : at most 1368 bytes and msg_sz is known in advance, thus we can use
411 : fd_log_collector_printf_*.
412 :
413 : TODO: implement based on fd_log_collector_msg_many(). */
414 : static inline void
415 33 : fd_log_collector_program_return( fd_exec_instr_ctx_t * ctx ) {
416 33 : if( FD_LIKELY( ctx->txn_ctx->log_collector.disabled ) ) {
417 33 : return;
418 33 : }
419 :
420 : /* ctx->txn_ctx->return_data is 1024 bytes max, so its base64 repr
421 : is at most (1024+2)/3*4 bytes, plus we use 1 byte for \0. */
422 0 : char return_base64[ (sizeof(ctx->txn_ctx->return_data.data)+2)/3*4+1 ];
423 0 : ulong sz = fd_base64_encode( return_base64, ctx->txn_ctx->return_data.data, ctx->txn_ctx->return_data.len );
424 0 : return_base64[ sz ] = 0;
425 : /* Max msg_sz: 21 - 4 + 44 + 1368 = 1429 < 1500 => we can use printf, but have to handle sz */
426 0 : ulong msg_sz = 17 + strlen(ctx->program_id_base58) + sz;
427 0 : if( msg_sz<=127 ) {
428 0 : fd_log_collector_printf_dangerous_max_127( ctx, "Program return: %s %s", ctx->program_id_base58, return_base64 );
429 0 : } else {
430 0 : fd_log_collector_printf_dangerous_128_to_2k( ctx, "Program return: %s %s", ctx->program_id_base58, return_base64 );
431 0 : }
432 0 : }
433 :
434 : /* fd_log_collector_program_success logs:
435 : "Program <ProgramIdBase58> success" */
436 : static inline void
437 12969 : fd_log_collector_program_success( fd_exec_instr_ctx_t * ctx ) {
438 : /* Max msg_sz: 18 - 2 + 44 = 60 < 127 => we can use printf */
439 12969 : fd_log_collector_printf_dangerous_max_127( ctx, "Program %s success", ctx->program_id_base58 );
440 12969 : }
441 :
442 : /* fd_log_collector_program_success logs:
443 : "Program <ProgramIdBase58> failed: <err>"
444 :
445 : This function handles the logic to log the correct msg, based
446 : on the type of error (InstructionError, SyscallError...).
447 : https://github.com/anza-xyz/agave/blob/v2.0.6/program-runtime/src/invoke_context.rs#L535-L549
448 :
449 : The error msg is obtained by external functions, e.g. fd_vm_syscall_strerror(),
450 : and can be either a valid msg or an empty string. Empty string represents
451 : special handling of the error log, for example the syscall panic logs directly
452 : the result, and therefore can be skipped at this stage. */
453 : static inline void
454 57759 : fd_log_collector_program_failure( fd_exec_instr_ctx_t * ctx ) {
455 57759 : if( FD_LIKELY( ctx->txn_ctx->log_collector.disabled ) ) {
456 3423 : return;
457 3423 : }
458 :
459 54336 : extern char const * fd_vm_ebpf_strerror( int err );
460 54336 : extern char const * fd_vm_syscall_strerror( int err );
461 54336 : extern char const * fd_executor_instr_strerror( int err );
462 :
463 54336 : char custom_err[33] = { 0 };
464 54336 : const char * err = custom_err;
465 54336 : const fd_exec_txn_ctx_t * txn_ctx = ctx->txn_ctx;
466 54336 : if( txn_ctx->custom_err != UINT_MAX ) {
467 : /* Max msg_sz = 32 <= 66 */
468 5502 : snprintf( custom_err, sizeof(custom_err), "custom program error: 0x%x", txn_ctx->custom_err );
469 48834 : } else if( txn_ctx->exec_err ) {
470 48834 : switch( txn_ctx->exec_err_kind ) {
471 237 : case FD_EXECUTOR_ERR_KIND_SYSCALL:
472 237 : err = fd_vm_syscall_strerror( txn_ctx->exec_err );
473 237 : break;
474 47391 : case FD_EXECUTOR_ERR_KIND_INSTR:
475 47391 : err = fd_executor_instr_strerror( txn_ctx->exec_err );
476 47391 : break;
477 1206 : default:
478 1206 : err = fd_vm_ebpf_strerror( txn_ctx->exec_err );
479 48834 : }
480 48834 : }
481 :
482 : /* Skip empty string, this means that the msg has already been logged. */
483 54336 : if( FD_LIKELY( err[0] ) ) {
484 54336 : char err_prefix[ 17+FD_BASE58_ENCODED_32_SZ ]; // 17==strlen("Program failed: ")
485 54336 : int err_prefix_len = sprintf( err_prefix, "Program %s failed: ", ctx->program_id_base58 );
486 54336 : if( err_prefix_len > 0 ) {
487 : /* Equivalent to: "Program %s failed: %s" */
488 54336 : fd_log_collector_msg_many( ctx, 2, err_prefix, (ulong)err_prefix_len, err, (ulong)strlen(err) );
489 54336 : }
490 54336 : }
491 54336 : }
492 :
493 : /* fd_log_collector_program_consumed logs:
494 : "Program <ProgramIdBase58> consumed <consumed> of <tota> compute units" */
495 : static inline void
496 1029 : fd_log_collector_program_consumed( fd_exec_instr_ctx_t * ctx, ulong consumed, ulong total ) {
497 : /* Max msg_sz: 44 - 8 + 44 + 20 + 20 = 120 < 127 => we can use printf */
498 1029 : fd_log_collector_printf_dangerous_max_127( ctx, "Program %s consumed %lu of %lu compute units", ctx->program_id_base58, consumed, total );
499 1029 : }
500 :
501 : /* DEBUG
502 : Only used for testing (inefficient but ok). */
503 :
504 : static inline ushort
505 2076 : fd_log_collector_debug_get_msg_sz( uchar const ** buf ) {
506 2076 : uchar msg0 = (*buf)[1];
507 2076 : uchar msg1 = (*buf)[2]; /* This is never oob */
508 2076 : int needs_2b = (msg0>0x7F);
509 2076 : ushort msg_sz = fd_ushort_if( needs_2b, (ushort)(((ushort)(msg1) << 7)|(msg0 & 0x7F)), (ushort)msg0 );
510 2076 : *buf += 2 + needs_2b;
511 2076 : return msg_sz;
512 2076 : }
513 :
514 : static inline ulong
515 30 : fd_log_collector_debug_len( fd_log_collector_t const * log ) {
516 30 : ulong len = 0;
517 63 : for( uchar const * cur = log->buf; cur < log->buf + log->buf_sz; ) {
518 33 : ushort cur_sz = fd_log_collector_debug_get_msg_sz( &cur );
519 33 : cur += cur_sz;
520 33 : ++len;
521 33 : }
522 30 : return len;
523 30 : }
524 :
525 : static inline uchar const *
526 : fd_log_collector_debug_get( fd_log_collector_t const * log,
527 : ulong log_num,
528 : uchar const ** msg,
529 15 : ulong * msg_sz ) {
530 15 : uchar const * cur = log->buf;
531 15 : ushort cur_sz = 0;
532 :
533 15 : cur_sz = fd_log_collector_debug_get_msg_sz( &cur );
534 24 : while( log_num>0 ) {
535 9 : cur += cur_sz;
536 9 : cur_sz = fd_log_collector_debug_get_msg_sz( &cur );
537 9 : --log_num;
538 9 : }
539 15 : if( msg ) *msg = cur;
540 15 : if( msg_sz ) *msg_sz = cur_sz;
541 15 : return cur;
542 15 : }
543 :
544 : static inline ulong
545 : fd_log_collector_debug_sprintf( fd_log_collector_t const * log,
546 : char * out,
547 2004 : int filter_zero ) {
548 2004 : ulong out_sz = 0;
549 :
550 2004 : ulong pos = 0;
551 2004 : uchar const * buf = log->buf;
552 4023 : while( pos < log->buf_sz ) {
553 : /* Read cur string sz */
554 2019 : ushort cur_sz = fd_log_collector_debug_get_msg_sz( &buf );
555 :
556 : /* Copy string and add \n.
557 : Slow version of memcpy that skips \0, because a \0 can be in logs.
558 : Equivalent to:
559 : fd_memcpy( out + out_sz, buf, cur_sz ); out_sz += cur_sz; */
560 2019 : if( filter_zero ) {
561 0 : for( ulong i=0; i<cur_sz; i++ ) {
562 0 : if( buf[i] ) {
563 0 : out[ out_sz++ ] = (char)buf[i];
564 0 : }
565 0 : }
566 2019 : } else {
567 2019 : fd_memcpy( out+out_sz, buf, cur_sz );
568 2019 : out_sz += cur_sz;
569 2019 : }
570 2019 : out[ out_sz++ ] = '\n';
571 :
572 : /* Move to next str */
573 2019 : buf += cur_sz;
574 2019 : pos = (ulong)(buf - log->buf);
575 2019 : }
576 :
577 : /* Remove the last \n, or return empty cstr */
578 2004 : out_sz = out_sz ? out_sz-1 : 0;
579 2004 : out[ out_sz ] = '\0';
580 2004 : return out_sz;
581 2004 : }
582 :
583 : static inline void
584 0 : fd_log_collector_private_debug( fd_log_collector_t const * log ) {
585 0 : char out[FD_LOG_COLLECTOR_MAX + FD_LOG_COLLECTOR_EXTRA];
586 0 : fd_log_collector_debug_sprintf( log, out, 1 );
587 0 : FD_LOG_WARNING(( "\n-----\n%s\n-----", out ));
588 0 : }
589 :
590 : FD_PROTOTYPES_END
591 :
592 : #endif /* HEADER_fd_src_flamenco_log_collector_fd_log_collector_h */
|
