The fiber's ID (fiber::fid) is unsigned integer so we should use a proper format specificator when printing it out, otherwise the logger show us weird strings like | main/-244760339/cartridge.failover.task I> Instance state changed Fixes #5846 Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com> --- src/lib/core/say.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/lib/core/say.c b/src/lib/core/say.c index cbd10e107..6138752a7 100644 --- a/src/lib/core/say.c +++ b/src/lib/core/say.c @@ -792,7 +792,7 @@ say_format_plain_tail(char *buf, int len, int level, const char *filename, if (cord) { SNPRINT(total, snprintf, buf, len, " %s", cord->name); if (fiber() && fiber()->fid != FIBER_ID_SCHED) { - SNPRINT(total, snprintf, buf, len, "/%i/%s", + SNPRINT(total, snprintf, buf, len, "/%u/%s", fiber()->fid, fiber_name(fiber())); } } @@ -918,7 +918,7 @@ say_format_json(struct log *log, char *buf, int len, int level, const char *file SNPRINT(total, snprintf, buf, len, "\""); if (fiber() && fiber()->fid != FIBER_ID_SCHED) { SNPRINT(total, snprintf, buf, len, - ", \"fiber_id\": %i, ", fiber()->fid); + ", \"fiber_id\": %u, ", fiber()->fid); SNPRINT(total, snprintf, buf, len, "\"fiber_name\": \""); SNPRINT(total, json_escape, buf, len, base-commit: 6610bce9bf43a139043518cd76d3c0c81c981ce2 -- 2.29.2
On Mon, Feb 22, 2021 at 09:20:30PM +0300, Cyrill Gorcunov wrote:
> The fiber's ID (fiber::fid) is unsigned integer so
> we should use a proper format specificator when printing
> it out, otherwise the logger show us weird strings like
>
> | main/-244760339/cartridge.failover.task I> Instance state changed
>
> Fixes #5846
>
> Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
Since it is one simple patch I though it doesn't deserve separate
branch but just in case pushed gorcunov/gh-5846-fid-name out.
Hi! Please, add a changelog file. This is user-visible behaviour so it must be reflected in the changes. On 22.02.2021 19:20, Cyrill Gorcunov wrote: > The fiber's ID (fiber::fid) is unsigned integer so > we should use a proper format specificator when printing > it out, otherwise the logger show us weird strings like > > | main/-244760339/cartridge.failover.task I> Instance state changed > > Fixes #5846 > > Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com> > --- > src/lib/core/say.c | 4 ++-- > 1 file changed, 2 insertions(+), 2 deletions(-) > > diff --git a/src/lib/core/say.c b/src/lib/core/say.c > index cbd10e107..6138752a7 100644 > --- a/src/lib/core/say.c > +++ b/src/lib/core/say.c > @@ -792,7 +792,7 @@ say_format_plain_tail(char *buf, int len, int level, const char *filename, > if (cord) { > SNPRINT(total, snprintf, buf, len, " %s", cord->name); > if (fiber() && fiber()->fid != FIBER_ID_SCHED) { > - SNPRINT(total, snprintf, buf, len, "/%i/%s", > + SNPRINT(total, snprintf, buf, len, "/%u/%s", > fiber()->fid, fiber_name(fiber())); I remember we had some issues about %u not being compatible with uint32_t so we did manual casts to 'unsigned'. Not sure though what was the commit/ticket, or if it really happened. I am fine with not using the cast as long as all platforms and compilers build flawlessly. Also it is ok for me if you will add an explicit cast in the next version of the patch. Up to you. The same below. > } > } > @@ -918,7 +918,7 @@ say_format_json(struct log *log, char *buf, int len, int level, const char *file > SNPRINT(total, snprintf, buf, len, "\""); > if (fiber() && fiber()->fid != FIBER_ID_SCHED) { > SNPRINT(total, snprintf, buf, len, > - ", \"fiber_id\": %i, ", fiber()->fid); > + ", \"fiber_id\": %u, ", fiber()->fid); > SNPRINT(total, snprintf, buf, len, > "\"fiber_name\": \""); > SNPRINT(total, json_escape, buf, len, > > base-commit: 6610bce9bf43a139043518cd76d3c0c81c981ce2
On Tue, Feb 23, 2021 at 09:41:46PM +0100, Vladislav Shpilevoy wrote: > Hi! Please, add a changelog file. This is user-visible behaviour > so it must be reflected in the changes. > > On 22.02.2021 19:20, Cyrill Gorcunov wrote: > > The fiber's ID (fiber::fid) is unsigned integer so > > we should use a proper format specificator when printing > > it out, otherwise the logger show us weird strings like > > > > | main/-244760339/cartridge.failover.task I> Instance state changed > > > > Fixes #5846 > > > > Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com> > > --- > > src/lib/core/say.c | 4 ++-- > > 1 file changed, 2 insertions(+), 2 deletions(-) > > > > diff --git a/src/lib/core/say.c b/src/lib/core/say.c > > index cbd10e107..6138752a7 100644 > > --- a/src/lib/core/say.c > > +++ b/src/lib/core/say.c > > @@ -792,7 +792,7 @@ say_format_plain_tail(char *buf, int len, int level, const char *filename, > > if (cord) { > > SNPRINT(total, snprintf, buf, len, " %s", cord->name); > > if (fiber() && fiber()->fid != FIBER_ID_SCHED) { > > - SNPRINT(total, snprintf, buf, len, "/%i/%s", > > + SNPRINT(total, snprintf, buf, len, "/%u/%s", > > fiber()->fid, fiber_name(fiber())); > > I remember we had some issues about %u not being compatible with uint32_t so > we did manual casts to 'unsigned'. Not sure though what was the commit/ticket, > or if it really happened. I suspect you rather mean uint64_t, which indeed better convert to excplicit "long long". Strictly speaking if we really need to cover compatibility we would _had_ to use PRIx macros which are so ugly :/ So no, uint32_t is known to be safe with %u format. Side note: I found that we still use %u for some of uint64_t, in particuar if (req->term < raft->volatile_term) { say_info("RAFT: the message is ignored due to outdated term - " "current term is %u", raft->volatile_term); return 0; } probably should use %llu and explicit "long long" for long standing servers where raft term would overflow 32 bit value. > > I am fine with not using the cast as long as all platforms and compilers > build flawlessly. Also it is ok for me if you will add an explicit cast in > the next version of the patch. Up to you. The same below. No, Vlad, I think we don't need explicit casts for 32bit values. I pushed an update to the branch gorcunov/gh-5846-fid-name and here is a new changelog. Does it look better? --- Subject: [PATCH] say: use unsigned format for fiber()->fid The fiber's ID (fiber::fid) is defined as unsigned integer so we should use a proper format specificator when printing it out. Currently logger prints such fibers as negative | main/-244760339/cartridge.failover.task I> Instance state changed why it should be | main/4271292179/cartridge.failover.task I> Instance state changed After the fix all fibers are logged with natural numbers (both in plain logger and json output formats) which might be considered as API change but should not cause any problems because if there were tools which scans for "zahlen" numbers they will scan for natural numbers without problems. After all there is no such things as fibers with negative numbers and when their fids are printed in Lua's "info" they are all natural (because they are converted into real numbers internally). Fixes #5846
>>> diff --git a/src/lib/core/say.c b/src/lib/core/say.c >>> index cbd10e107..6138752a7 100644 >>> --- a/src/lib/core/say.c >>> +++ b/src/lib/core/say.c >>> @@ -792,7 +792,7 @@ say_format_plain_tail(char *buf, int len, int level, const char *filename, >>> if (cord) { >>> SNPRINT(total, snprintf, buf, len, " %s", cord->name); >>> if (fiber() && fiber()->fid != FIBER_ID_SCHED) { >>> - SNPRINT(total, snprintf, buf, len, "/%i/%s", >>> + SNPRINT(total, snprintf, buf, len, "/%u/%s", >>> fiber()->fid, fiber_name(fiber())); >> >> I remember we had some issues about %u not being compatible with uint32_t so >> we did manual casts to 'unsigned'. Not sure though what was the commit/ticket, >> or if it really happened. > > I suspect you rather mean uint64_t, which indeed better convert to > excplicit "long long". No, I mean exactly uint32_t. You don't have a guarantee that it is the same as 'unsigned' AFAIK. > Strictly speaking if we really need to cover > compatibility we would _had_ to use PRIx macros which are so ugly :/ This is why I want us to use casts to 'unsigned' when we use %u. They are less ugly. > So no, uint32_t is known to be safe with %u format. Is it written in the standard somewhere? I honestly don't know. > Side note: I found that we still use %u for some of uint64_t, > in particuar > > if (req->term < raft->volatile_term) { > say_info("RAFT: the message is ignored due to outdated term - " > "current term is %u", raft->volatile_term); > return 0; > } > > probably should use %llu and explicit "long long" for long standing > servers where raft term would overflow 32 bit value. Yes, looks like a bug. But a more appropriate fix would be to investigate why don't we have compile time checks for this. The bug in raft's say_info() is clearly an error and should have been alarmed at compilation. At least clang supports an attribute which you can set for a function and get printf-like checks and warnings in case of format issues. We should adopt this: https://clang.llvm.org/docs/AttributeReference.html#id278 Somewhy I thought we already use it, but now I don't see any usages. It is easy to add, and helps to catch some weird stuff. Lets do it in scope of this patch series to fix the issue entirely. Not just in one exploded place. >> I am fine with not using the cast as long as all platforms and compilers >> build flawlessly. Also it is ok for me if you will add an explicit cast in >> the next version of the patch. Up to you. The same below. > > No, Vlad, I think we don't need explicit casts for 32bit values. Do you have a proof for this? That it is safe. Where in the standard do they say that '%u' is exactly 4 bytes? > I pushed > an update to the branch gorcunov/gh-5846-fid-name and here is a new > changelog. Does it look better? It seems you didn't really read my comment, did you? I said: "Please, add a changelog file" I didn't ask for more info in the commit message. This particular bug in this particular line was obvious. But you didn't add a changelog **file**. It should be added here: https://github.com/tarantool/tarantool/tree/master/changelogs/unreleased After more consideration I also realized we should not use uint32_t for fiber ids. It is monotonically growing. Which means it will overflow in the foreseeable future on a long-running instance. For example, assume one fiber is started and recycled each millisecond (which is quite a small rate). Then uint32 will overflow in less than 50 days. Considering we have instances running for years (at least from what I heard from Mons), this is clearly a bug. On the summary, it seems we need to - Add compile-time format checks using clang __format__ attribute; - Fix all the wrong formats; - Use 64bit ids for fibers. Unless I am wrong somewhere in my thoughts above.
On Tue, Feb 23, 2021 at 11:47:44PM +0100, Vladislav Shpilevoy wrote: > >>> diff --git a/src/lib/core/say.c b/src/lib/core/say.c > >>> index cbd10e107..6138752a7 100644 > >>> --- a/src/lib/core/say.c > >>> +++ b/src/lib/core/say.c > >>> @@ -792,7 +792,7 @@ say_format_plain_tail(char *buf, int len, int level, const char *filename, > >>> if (cord) { > >>> SNPRINT(total, snprintf, buf, len, " %s", cord->name); > >>> if (fiber() && fiber()->fid != FIBER_ID_SCHED) { > >>> - SNPRINT(total, snprintf, buf, len, "/%i/%s", > >>> + SNPRINT(total, snprintf, buf, len, "/%u/%s", > >>> fiber()->fid, fiber_name(fiber())); > >> > >> I remember we had some issues about %u not being compatible with uint32_t so > >> we did manual casts to 'unsigned'. Not sure though what was the commit/ticket, > >> or if it really happened. > > > > I suspect you rather mean uint64_t, which indeed better convert to > > excplicit "long long". > > No, I mean exactly uint32_t. You don't have a guarantee that it is > the same as 'unsigned' AFAIK. It is, on x86. And I really doubt if we ever meet an arch where int is not 4 bytes long. Though in embedded world this might be a common situation (but if we aim ourself to run tarantool here the output issue gonna be a least problem). > > > Strictly speaking if we really need to cover > > compatibility we would _had_ to use PRIx macros which are so ugly :/ > > This is why I want us to use casts to 'unsigned' when we use %u. They > are less ugly. We will have to cover a bunch of already existing code for nothing :( But OK, I'll add explicit cast. > > > So no, uint32_t is known to be safe with %u format. > > Is it written in the standard somewhere? I honestly don't know. Standart for builtin types doesn't cover the size of machine words as far as I remember because this would tie a hands for compiler developers which have to deal with custom archs. It specifies the integer classes covering and on x86 we know that we're safe. But as I said I'll add explicit cast. > > Side note: I found that we still use %u for some of uint64_t, > > in particuar > > > > if (req->term < raft->volatile_term) { > > say_info("RAFT: the message is ignored due to outdated term - " > > "current term is %u", raft->volatile_term); > > return 0; > > } > > > > probably should use %llu and explicit "long long" for long standing > > servers where raft term would overflow 32 bit value. > > Yes, looks like a bug. Should not be critical, though. It is logging for debug mostly but we should fix it. > But a more appropriate fix would be to investigate why don't we have > compile time checks for this. The bug in raft's say_info() is clearly > an error and should have been alarmed at compilation. We have kind of check /** Internal function used to implement say() macros */ CFORMAT(printf, 5, 0) extern sayfunc_t _say; still I must confess I don't know yet why it didn't trigger, need to investigate. > At least clang supports an attribute which you can set for a function > and get printf-like checks and warnings in case of format issues. > > We should adopt this: https://clang.llvm.org/docs/AttributeReference.html#id278 > > Somewhy I thought we already use it, but now I don't see any usages. > It is easy to add, and helps to catch some weird stuff. > > Lets do it in scope of this patch series to fix the issue entirely. Not > just in one exploded place. OK > > >> I am fine with not using the cast as long as all platforms and compilers > >> build flawlessly. Also it is ok for me if you will add an explicit cast in > >> the next version of the patch. Up to you. The same below. > > > > No, Vlad, I think we don't need explicit casts for 32bit values. > > Do you have a proof for this? That it is safe. Where in the standard do they > say that '%u' is exactly 4 bytes? Already explained. I'll make it use explicit cast though I still think it is redundant. > > I pushed > > an update to the branch gorcunov/gh-5846-fid-name and here is a new > > changelog. Does it look better? > > It seems you didn't really read my comment, did you? I said: > > "Please, add a changelog file" > > I didn't ask for more info in the commit message. This particular > bug in this particular line was obvious. > > But you didn't add a changelog **file**. It should be added here: > https://github.com/tarantool/tarantool/tree/master/changelogs/unreleased Ah, you mean this new tecique for changelogs. OK, misread your comment, at first I thought to update commit message for better export into changelog. Will do. > > After more consideration I also realized we should not use uint32_t > for fiber ids. It is monotonically growing. Which means it will overflow > in the foreseeable future on a long-running instance. - it is explected to be overlowable from the beginning - the IDs are recycled I've been talking to Kostya about a year ago once I discovered that we're walking in cycle when reusing IDs. He assured me that this is fine and to get a problem we have to allocate 4294967195 fibers at once which will require ~1.5T of memory just to allocate fiber structure. Hardy to happen. Still I think we at least should add a painc in case of hash collision for future. > For example, assume one fiber is started and recycled each millisecond > (which is quite a small rate). Then uint32 will overflow in less than > 50 days. Considering we have instances running for years (at least from > what I heard from Mons), this is clearly a bug. > > On the summary, it seems we need to > > - Add compile-time format checks using clang __format__ attribute; > - Fix all the wrong formats; +1 > - Use 64bit ids for fibers. Unless I am wrong somewhere in my thoughts > above. This is dubious. Personally I would prefer to have them as uint64_t too now and for all, to simply forget about this potential issue. +4 bytes to fiber structure seems to be acceptable trade off. Cyrill
When been fixing issue 5846 we've found that our format specification test simply doesn't work. Lets use proper formatting and turn it back on. Guys, I split the series per-file for better review and probably fixups if there will be a need. After all committer may simply merge all them except the first one. issue https://github.com/tarantool/tarantool/issues/5846 branch gorcunov/gh-5846-fid-name-2 v2: - add changelog - revisit CFORMAT - fix all warnings covered so far Cyrill Gorcunov (10): say: use unsigned format for fiber()->fid popen: fix say_x format arguments raft: fix say_x arguments box/error: fix argument for CustomError xlog: fix say_x format box/vynil: fix say_x format txn: fix say_x format limbo: fix say_x format wal: fix say_x format say: fix CFORMAT specification changelogs/unreleased/fix-fiber-fid-log.md | 5 +++++ src/box/error.cc | 2 +- src/box/txn.c | 3 ++- src/box/txn_limbo.c | 2 +- src/box/vy_scheduler.c | 2 +- src/box/wal.c | 15 ++++++++------- src/box/xlog.c | 4 ++-- src/lib/core/popen.c | 4 ++-- src/lib/core/say.c | 6 +++--- src/lib/core/say.h | 2 +- src/lib/raft/raft.c | 5 +++-- 11 files changed, 29 insertions(+), 21 deletions(-) create mode 100644 changelogs/unreleased/fix-fiber-fid-log.md base-commit: 6610bce9bf43a139043518cd76d3c0c81c981ce2 -- 2.29.2
The fiber's ID (fiber::fid) is defined as unsigned integer so we should use a proper format specificator when printing it out. Currently logger prints such fibers as negative | main/-244760339/cartridge.failover.task I> Instance state changed why it should be | main/4271292179/cartridge.failover.task I> Instance state changed After the fix all fibers are logged with natural numbers (both in plain logger and json output formats). Fixes #5846 Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com> --- changelogs/unreleased/fix-fiber-fid-log.md | 5 +++++ src/lib/core/say.c | 6 +++--- 2 files changed, 8 insertions(+), 3 deletions(-) create mode 100644 changelogs/unreleased/fix-fiber-fid-log.md diff --git a/changelogs/unreleased/fix-fiber-fid-log.md b/changelogs/unreleased/fix-fiber-fid-log.md new file mode 100644 index 000000000..fb75af804 --- /dev/null +++ b/changelogs/unreleased/fix-fiber-fid-log.md @@ -0,0 +1,5 @@ +## bugfix/core + +* Fix logger output for fiber id: format specificator has been + using signed integers while fibers actually are defined as + unsigned numbers (gh-5846). diff --git a/src/lib/core/say.c b/src/lib/core/say.c index cbd10e107..76c524872 100644 --- a/src/lib/core/say.c +++ b/src/lib/core/say.c @@ -792,8 +792,8 @@ say_format_plain_tail(char *buf, int len, int level, const char *filename, if (cord) { SNPRINT(total, snprintf, buf, len, " %s", cord->name); if (fiber() && fiber()->fid != FIBER_ID_SCHED) { - SNPRINT(total, snprintf, buf, len, "/%i/%s", - fiber()->fid, fiber_name(fiber())); + SNPRINT(total, snprintf, buf, len, "/%u/%s", + (unsigned)fiber()->fid, fiber_name(fiber())); } } @@ -918,7 +918,7 @@ say_format_json(struct log *log, char *buf, int len, int level, const char *file SNPRINT(total, snprintf, buf, len, "\""); if (fiber() && fiber()->fid != FIBER_ID_SCHED) { SNPRINT(total, snprintf, buf, len, - ", \"fiber_id\": %i, ", fiber()->fid); + ", \"fiber_id\": %u, ", (unsigned)fiber()->fid); SNPRINT(total, snprintf, buf, len, "\"fiber_name\": \""); SNPRINT(total, json_escape, buf, len, -- 2.29.2
Drop redundant "%s" from format. Part-of #5846 Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com> --- src/lib/core/popen.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/lib/core/popen.c b/src/lib/core/popen.c index 3b5fd1062..99a3d3cbd 100644 --- a/src/lib/core/popen.c +++ b/src/lib/core/popen.c @@ -240,7 +240,7 @@ handle_new(struct popen_opts *opts) static inline void handle_free(struct popen_handle *handle) { - say_debug("popen: handle %p free %p", handle); + say_debug("popen: handle free %p", handle); free(handle); } @@ -533,7 +533,7 @@ popen_shutdown(struct popen_handle *handle, unsigned int flags) if (handle->ios[idx].fd < 0) continue; - say_debug("popen: %d: shutdown idx [%s:%d] fd %s", + say_debug("popen: %d: shutdown idx [%s:%zd] fd %d", handle->pid, stdX_str(idx), idx, handle->ios[idx].fd); coio_close_io(loop(), &handle->ios[idx]); -- 2.29.2
Use explicit "%lld" for int64_t type. Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com> --- src/lib/raft/raft.c | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/src/lib/raft/raft.c b/src/lib/raft/raft.c index 4ea4fc3f8..261ff072b 100644 --- a/src/lib/raft/raft.c +++ b/src/lib/raft/raft.c @@ -322,7 +322,8 @@ raft_process_msg(struct raft *raft, const struct raft_msg *req, uint32_t source) /* Outdated request. */ if (req->term < raft->volatile_term) { say_info("RAFT: the message is ignored due to outdated term - " - "current term is %u", raft->volatile_term); + "current term is %llu", + (long long)raft->volatile_term); return 0; } @@ -653,7 +654,7 @@ raft_sm_become_candidate(struct raft *raft) static void raft_sm_schedule_new_term(struct raft *raft, uint64_t new_term) { - say_info("RAFT: bump term to %llu, follow", new_term); + say_info("RAFT: bump term to %llu, follow", (long long)new_term); assert(new_term > raft->volatile_term); assert(raft->volatile_term >= raft->term); raft->volatile_term = new_term; -- 2.29.2
Drop redundant "%s" argument. Part-of #5846 Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com> --- src/box/error.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/box/error.cc b/src/box/error.cc index f3b4ffe86..225b377b7 100644 --- a/src/box/error.cc +++ b/src/box/error.cc @@ -345,7 +345,7 @@ CustomError::CustomError(const char *file, unsigned int line, void CustomError::log() const { - say_file_line(S_ERROR, file, line, errmsg, "%s", + say_file_line(S_ERROR, file, line, errmsg, "Custom type %s", m_custom_type); } -- 2.29.2
The string length specificator expects length as integer value. Part-of #5846 Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com> --- src/box/xlog.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/box/xlog.c b/src/box/xlog.c index 974f460be..40c07abf0 100644 --- a/src/box/xlog.c +++ b/src/box/xlog.c @@ -314,8 +314,8 @@ xlog_meta_parse(struct xlog_meta *meta, const char **data, /* * Unknown key */ - say_warn("Unknown meta item: `%.*s'", key_end - key, - key); + say_warn("Unknown meta item: `%.*s'", + (int)(key_end - key), key); } } *data = end + 1; /* skip the last trailing \n of \n\n sequence */ -- 2.29.2
Drop redundant "%s" from format. Part-of #5846 Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com> --- src/box/vy_scheduler.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/box/vy_scheduler.c b/src/box/vy_scheduler.c index b641dd9b8..6f6e9c340 100644 --- a/src/box/vy_scheduler.c +++ b/src/box/vy_scheduler.c @@ -1714,7 +1714,7 @@ vy_task_compaction_new(struct vy_scheduler *scheduler, struct vy_worker *worker, vy_task_delete(task); err_task: diag_log(); - say_error("%s: could not start compacting range %s: %s", + say_error("%s: could not start compacting range %s", vy_lsm_name(lsm), vy_range_str(range)); return -1; } -- 2.29.2
Use explicit conversion for 64 bit number. Part-of #5846 Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com> --- src/box/txn.c | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/box/txn.c b/src/box/txn.c index a5edbfc60..c9c0579b8 100644 --- a/src/box/txn.c +++ b/src/box/txn.c @@ -585,7 +585,8 @@ txn_on_journal_write(struct journal_entry *entry) int n_rows = txn->n_new_rows + txn->n_applier_rows; say_warn_ratelimited("too long WAL write: %d rows at LSN %lld: " "%.3f sec", n_rows, - txn->signature - n_rows + 1, delta); + (long long)(txn->signature - n_rows + 1), + delta); } if (txn_has_flag(txn, TXN_HAS_TRIGGERS)) txn_run_wal_write_triggers(txn); -- 2.29.2
Use explicit cast for 64 bit number. Part-of #5846 Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com> --- src/box/txn_limbo.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/box/txn_limbo.c b/src/box/txn_limbo.c index 9c4c3cdf1..0ca4a478a 100644 --- a/src/box/txn_limbo.c +++ b/src/box/txn_limbo.c @@ -354,7 +354,7 @@ txn_limbo_write_synchro(struct txn_limbo *limbo, uint32_t type, int64_t lsn) * Or retry automatically with some period. */ panic("Could not write a synchro request to WAL: " - "lsn = %lld, type = %s\n", lsn, + "lsn = %lld, type = %s\n", (long long)lsn, iproto_type_name(type)); } } -- 2.29.2
- vclock_get returns int64_t - vclock_sum returns int64_t Part-of #5846 Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com> --- src/box/wal.c | 15 ++++++++------- 1 file changed, 8 insertions(+), 7 deletions(-) diff --git a/src/box/wal.c b/src/box/wal.c index 937d47ba9..1c0076f26 100644 --- a/src/box/wal.c +++ b/src/box/wal.c @@ -993,13 +993,14 @@ wal_assign_lsn(struct vclock *vclock_diff, struct vclock *base, int64_t diff = (*row)->lsn - vclock_get(base, (*row)->replica_id); if (diff <= vclock_get(vclock_diff, (*row)->replica_id)) { + int64_t confirmed_lsn = + vclock_get(base, (*row)->replica_id) + + vclock_get(vclock_diff, (*row)->replica_id); say_crit("Attempt to write a broken LSN to WAL:" - " replica id: %d, confirmed lsn: %d," - " new lsn %d", (*row)->replica_id, - vclock_get(base, (*row)->replica_id) + - vclock_get(vclock_diff, - (*row)->replica_id), - (*row)->lsn); + " replica id: %d, confirmed lsn: %lld," + " new lsn %lld", (*row)->replica_id, + (long long)confirmed_lsn, + (long long)(*row)->lsn); assert(false); } else { vclock_follow(vclock_diff, (*row)->replica_id, diff); @@ -1241,7 +1242,7 @@ wal_write_async(struct journal *journal, struct journal_entry *entry) */ say_error("Aborting transaction %llu during " "cascading rollback", - vclock_sum(&writer->vclock)); + (long long)vclock_sum(&writer->vclock)); goto fail; } -- 2.29.2
The position of first argument to check from is 6, not 0. Looks like our tests with CFORMAT was simply not working since commit 7d12d66e67a1ce843a2712980f4d3ba04bc0d4f2. Lets turn them all back. Part-of #5846 Reported-by: Vladislav Shpilevoy <v.shpilevoy@tarantool.org> Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com> --- src/lib/core/say.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/lib/core/say.h b/src/lib/core/say.h index fe8251e4c..e1fec8c60 100644 --- a/src/lib/core/say.h +++ b/src/lib/core/say.h @@ -287,7 +287,7 @@ typedef void (*sayfunc_t)(int, const char *, int, const char *, const char *, ...); /** Internal function used to implement say() macros */ -CFORMAT(printf, 5, 0) extern sayfunc_t _say; +CFORMAT(printf, 5, 6) extern sayfunc_t _say; /** * Format and print a message to Tarantool log file. -- 2.29.2
On 24.02.2021 09:28, Cyrill Gorcunov wrote: > On Tue, Feb 23, 2021 at 11:47:44PM +0100, Vladislav Shpilevoy wrote: >>>>> diff --git a/src/lib/core/say.c b/src/lib/core/say.c >>>>> index cbd10e107..6138752a7 100644 >>>>> --- a/src/lib/core/say.c >>>>> +++ b/src/lib/core/say.c >>>>> @@ -792,7 +792,7 @@ say_format_plain_tail(char *buf, int len, int level, const char *filename, >>>>> if (cord) { >>>>> SNPRINT(total, snprintf, buf, len, " %s", cord->name); >>>>> if (fiber() && fiber()->fid != FIBER_ID_SCHED) { >>>>> - SNPRINT(total, snprintf, buf, len, "/%i/%s", >>>>> + SNPRINT(total, snprintf, buf, len, "/%u/%s", >>>>> fiber()->fid, fiber_name(fiber())); >>>> >>>> I remember we had some issues about %u not being compatible with uint32_t so >>>> we did manual casts to 'unsigned'. Not sure though what was the commit/ticket, >>>> or if it really happened. >>> >>> I suspect you rather mean uint64_t, which indeed better convert to >>> excplicit "long long". >> >> No, I mean exactly uint32_t. You don't have a guarantee that it is >> the same as 'unsigned' AFAIK. > > It is, on x86. In the close future we will build on the new ARM Macs. Simply because many of our developers use Macs and they want the new models. All our assumptions about x86 being the only platform should not be made anymore. >>> Strictly speaking if we really need to cover >>> compatibility we would _had_ to use PRIx macros which are so ugly :/ >> >> This is why I want us to use casts to 'unsigned' when we use %u. They >> are less ugly. > > We will have to cover a bunch of already existing code for nothing :( > But OK, I'll add explicit cast. It is ok to keep the old code intact where the compiler won't give any errors when you enable the compile time checking. >> After more consideration I also realized we should not use uint32_t >> for fiber ids. It is monotonically growing. Which means it will overflow >> in the foreseeable future on a long-running instance. > > - it is explected to be overlowable from the beginning Why? It is not safe. There is no any protection in case of overflow and ids clash. > - the IDs are recycled Exactly. They start recycle on overflow. This means if you had a long living fiber for 50 days, and the scenario described by me happens, you will get id clash. > I've been talking to Kostya about a year ago once I discovered that > we're walking in cycle when reusing IDs. He assured me that this is > fine and to get a problem we have to allocate 4294967195 fibers at > once which will require ~1.5T of memory just to allocate fiber structure. It is not about at once. It is about long running instances. > Hardy to happen. Still I think we at least should add a painc in case of > hash collision for future. We should just make it int64_t and forget about it IMO. >> - Use 64bit ids for fibers. Unless I am wrong somewhere in my thoughts >> above. > > This is dubious. Personally I would prefer to have them as uint64_t too > now and for all, to simply forget about this potential issue. +4 bytes > to fiber structure seems to be acceptable trade off. Exactly.
Hi! Thanks for the patch! On 24.02.2021 16:36, Cyrill Gorcunov wrote: > Drop redundant "%s" from format. Neither of the changes below are about dropping a redundant %s. First one drops %p, second one replaces it with %d and fixes size_t. > Part-of #5846 > > Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com> > --- > src/lib/core/popen.c | 4 ++-- > 1 file changed, 2 insertions(+), 2 deletions(-) > > diff --git a/src/lib/core/popen.c b/src/lib/core/popen.c > index 3b5fd1062..99a3d3cbd 100644 > --- a/src/lib/core/popen.c > +++ b/src/lib/core/popen.c > @@ -240,7 +240,7 @@ handle_new(struct popen_opts *opts) > static inline void > handle_free(struct popen_handle *handle) > { > - say_debug("popen: handle %p free %p", handle); > + say_debug("popen: handle free %p", handle); > free(handle); > } > > @@ -533,7 +533,7 @@ popen_shutdown(struct popen_handle *handle, unsigned int flags) > if (handle->ios[idx].fd < 0) > continue; > > - say_debug("popen: %d: shutdown idx [%s:%d] fd %s", > + say_debug("popen: %d: shutdown idx [%s:%zd] fd %d", > handle->pid, stdX_str(idx), idx, > handle->ios[idx].fd); > coio_close_io(loop(), &handle->ios[idx]); >
Thanks for the patch! On 24.02.2021 16:36, Cyrill Gorcunov wrote: > Use explicit "%lld" for int64_t type. In the changes you use %llu in both cases. > Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com> > --- > src/lib/raft/raft.c | 5 +++-- > 1 file changed, 3 insertions(+), 2 deletions(-) > > diff --git a/src/lib/raft/raft.c b/src/lib/raft/raft.c > index 4ea4fc3f8..261ff072b 100644 > --- a/src/lib/raft/raft.c > +++ b/src/lib/raft/raft.c > @@ -322,7 +322,8 @@ raft_process_msg(struct raft *raft, const struct raft_msg *req, uint32_t source) > /* Outdated request. */ > if (req->term < raft->volatile_term) { > say_info("RAFT: the message is ignored due to outdated term - " > - "current term is %u", raft->volatile_term); > + "current term is %llu", > + (long long)raft->volatile_term); It is unsigned. So the cast must be 'unsigned long long'. The same below. > return 0; > } > > @@ -653,7 +654,7 @@ raft_sm_become_candidate(struct raft *raft) > static void > raft_sm_schedule_new_term(struct raft *raft, uint64_t new_term) > { > - say_info("RAFT: bump term to %llu, follow", new_term); > + say_info("RAFT: bump term to %llu, follow", (long long)new_term); > assert(new_term > raft->volatile_term); > assert(raft->volatile_term >= raft->term); > raft->volatile_term = new_term; >
Thanks for the patch! On 24.02.2021 16:36, Cyrill Gorcunov wrote: > The string length specificator expects length as > integer value. > > Part-of #5846 > > Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com> > --- > src/box/xlog.c | 4 ++-- > 1 file changed, 2 insertions(+), 2 deletions(-) > > diff --git a/src/box/xlog.c b/src/box/xlog.c > index 974f460be..40c07abf0 100644 > --- a/src/box/xlog.c > +++ b/src/box/xlog.c > @@ -314,8 +314,8 @@ xlog_meta_parse(struct xlog_meta *meta, const char **data, > /* > * Unknown key > */ > - say_warn("Unknown meta item: `%.*s'", key_end - key, > - key); > + say_warn("Unknown meta item: `%.*s'", The quotes around %s are inconsistent: `' instead of '' or ``. Lets use ''. I know it was there before your patch, but lets fix it anyway, considering it a part of the format. > + (int)(key_end - key), key); > } > } > *data = end + 1; /* skip the last trailing \n of \n\n sequence */ >
Thanks for the patch! On 24.02.2021 16:36, Cyrill Gorcunov via Tarantool-patches wrote: > - vclock_get returns int64_t > - vclock_sum returns int64_t > > Part-of #5846 > > Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com> > --- > src/box/wal.c | 15 ++++++++------- > 1 file changed, 8 insertions(+), 7 deletions(-) > > diff --git a/src/box/wal.c b/src/box/wal.c > index 937d47ba9..1c0076f26 100644 > --- a/src/box/wal.c > +++ b/src/box/wal.c > @@ -993,13 +993,14 @@ wal_assign_lsn(struct vclock *vclock_diff, struct vclock *base, > int64_t diff = (*row)->lsn - vclock_get(base, (*row)->replica_id); > if (diff <= vclock_get(vclock_diff, > (*row)->replica_id)) { > + int64_t confirmed_lsn = > + vclock_get(base, (*row)->replica_id) + > + vclock_get(vclock_diff, (*row)->replica_id); > say_crit("Attempt to write a broken LSN to WAL:" > - " replica id: %d, confirmed lsn: %d," > - " new lsn %d", (*row)->replica_id, > - vclock_get(base, (*row)->replica_id) + > - vclock_get(vclock_diff, > - (*row)->replica_id), > - (*row)->lsn); > + " replica id: %d, confirmed lsn: %lld," `replica_id` is uint32_t. So it should be %u and cast to (unsigned) I suppose. > + " new lsn %lld", (*row)->replica_id, > + (long long)confirmed_lsn, > + (long long)(*row)->lsn); > assert(false); > } else { > vclock_follow(vclock_diff, (*row)->replica_id, diff); > @@ -1241,7 +1242,7 @@ wal_write_async(struct journal *journal, struct journal_entry *entry) > */ > say_error("Aborting transaction %llu during " > "cascading rollback", > - vclock_sum(&writer->vclock)); > + (long long)vclock_sum(&writer->vclock)); Long long should use %lld, not %llu. I have no idea why is the format checker silent about this.
Thanks for the patch!
On 24.02.2021 16:36, Cyrill Gorcunov via Tarantool-patches wrote:
> The position of first argument to check from is 6, not 0.
> Looks like our tests with CFORMAT was simply not working
> since commit 7d12d66e67a1ce843a2712980f4d3ba04bc0d4f2.
Please, add the commit title here in braces like we usually do
when reference old commits.
Thanks for the patch!
This bug could actually lead to a crash. Because the printer would
try to read memory by a not passed string pointer.
Nikita, does it look related to any of the crashes we have in vinyl?
On 24.02.2021 16:36, Cyrill Gorcunov wrote:
> Drop redundant "%s" from format.
>
> Part-of #5846
>
> Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
> ---
> src/box/vy_scheduler.c | 2 +-
> 1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/src/box/vy_scheduler.c b/src/box/vy_scheduler.c
> index b641dd9b8..6f6e9c340 100644
> --- a/src/box/vy_scheduler.c
> +++ b/src/box/vy_scheduler.c
> @@ -1714,7 +1714,7 @@ vy_task_compaction_new(struct vy_scheduler *scheduler, struct vy_worker *worker,
> vy_task_delete(task);
> err_task:
> diag_log();
> - say_error("%s: could not start compacting range %s: %s",
> + say_error("%s: could not start compacting range %s",
> vy_lsm_name(lsm), vy_range_str(range));
> return -1;
> }
>
On Wed, Feb 24, 2021 at 11:39:39PM +0100, Vladislav Shpilevoy wrote:
> Hi! Thanks for the patch!
>
> On 24.02.2021 16:36, Cyrill Gorcunov wrote:
> > Drop redundant "%s" from format.
>
> Neither of the changes below are about dropping a redundant %s.
> First one drops %p, second one replaces it with %d and fixes
> size_t.
Sigh, sorry. This slipped in from series reordering. Thanks for catching!
On Wed, Feb 24, 2021 at 11:39:47PM +0100, Vladislav Shpilevoy wrote: > Thanks for the patch! > > On 24.02.2021 16:36, Cyrill Gorcunov wrote: > > Use explicit "%lld" for int64_t type. > > In the changes you use %llu in both cases. Good catch! Thanks. > > @@ -322,7 +322,8 @@ raft_process_msg(struct raft *raft, const struct raft_msg *req, uint32_t source) > > /* Outdated request. */ > > if (req->term < raft->volatile_term) { > > say_info("RAFT: the message is ignored due to outdated term - " > > - "current term is %u", raft->volatile_term); > > + "current term is %llu", > > + (long long)raft->volatile_term); > > It is unsigned. So the cast must be 'unsigned long long'. > The same below. Atually this is done on a purpose. Signed/unsigned objects are kept in same amount of memory storage, which is guaranteed by the standart. We can use (long long) here to specify the size of object while the sign gonna be interpreted by formatter itself, and this is what our static formatter does test -- storage size. So no, I think we can continue use (long long) specificator here.
On Wed, Feb 24, 2021 at 11:41:18PM +0100, Vladislav Shpilevoy wrote:
> > say_error("Aborting transaction %llu during "
> > "cascading rollback",
> > - vclock_sum(&writer->vclock));
> > + (long long)vclock_sum(&writer->vclock));
>
> Long long should use %lld, not %llu. I have no idea why is the format checker
> silent about this.
Because they are same in size and can be freely exchanged, io it is
up to you hot to interpret data inside formatter as signed or unsigned,
the cast must provide the _size_ of argument, not its sign.
On 24 Feb 23:43, Vladislav Shpilevoy wrote: > Thanks for the patch! > > This bug could actually lead to a crash. Because the printer would > try to read memory by a not passed string pointer. > > Nikita, does it look related to any of the crashes we have in vinyl? No, it doesn't. Errors at compatin start are rather rare. > On 24.02.2021 16:36, Cyrill Gorcunov wrote: > > Drop redundant "%s" from format. > > > > Part-of #5846 > > > > Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com> > > --- > > src/box/vy_scheduler.c | 2 +- > > 1 file changed, 1 insertion(+), 1 deletion(-) > > > > diff --git a/src/box/vy_scheduler.c b/src/box/vy_scheduler.c > > index b641dd9b8..6f6e9c340 100644 > > --- a/src/box/vy_scheduler.c > > +++ b/src/box/vy_scheduler.c > > @@ -1714,7 +1714,7 @@ vy_task_compaction_new(struct vy_scheduler *scheduler, struct vy_worker *worker, > > vy_task_delete(task); > > err_task: > > diag_log(); > > - say_error("%s: could not start compacting range %s: %s", > > + say_error("%s: could not start compacting range %s", > > vy_lsm_name(lsm), vy_range_str(range)); > > return -1; > > } > >