search

folkertvanheusden / multitail

Tail on steroids
https://vanheusden.com/multitail/
MIT License
129 stars 13 forks source link

Multitail crashes #35

Closed mikaelz closed 4 months ago

mikaelz commented 7 months ago

Hi, currently docker logs are crashing which used to work for me months, but now the following error is show when I start multitail

multitail: /home/mike/.cache/yay/multitail/src/multitail-7.1.2/utils.c:366: amount_to_str: Assertion `amount >= 0' failed.
[1]    1554186 IOT instruction (core dumped)  multitail -cS monolog -l 'docker-compose logs --no-color -f ws-app-services'

In journalctl

Apr 05 07:12:51 mike-pc systemd-coredump[1554216]: Process 1554186 (multitail) of user 1000 dumped core.

                                                   Stack trace of thread 1554186:
                                                   #0  0x00007e28654b832c n/a (libc.so.6 + 0x8d32c)
                                                   #1  0x00007e28654676c8 raise (libc.so.6 + 0x3c6c8)
                                                   #2  0x00007e286544f4b8 abort (libc.so.6 + 0x244b8)
                                                   #3  0x00007e286544f3dc n/a (libc.so.6 + 0x243dc)
                                                   #4  0x00007e286545fd46 __assert_fail (libc.so.6 + 0x34d46)
                                                   #5  0x00005e8426a2e899 n/a (multitail + 0x1d899)
                                                   #6  0x00005e8426a20b2f n/a (multitail + 0xfb2f)
                                                   #7  0x00005e8426a2764f n/a (multitail + 0x1664f)
                                                   #8  0x00005e8426a29f2f n/a (multitail + 0x18f2f)
                                                   #9  0x00005e8426a1575a n/a (multitail + 0x475a)
                                                   #10 0x00007e2865450cd0 n/a (libc.so.6 + 0x25cd0)
                                                   #11 0x00007e2865450d8a __libc_start_main (libc.so.6 + 0x25d8a)
                                                   #12 0x00005e8426a15d05 n/a (multitail + 0x4d05)
                                                   ELF object binary architecture: AMD x86-64

Docker log first rows

WARN[0000] The "WS_CROWDIN_ACCESS_TOKEN" variable is not set. Defaulting to a blank string. 
WARN[0000] The "WS_CROWDIN_ACCESS_TOKEN" variable is not set. Defaulting to a blank string. 
WARN[0000] /development-stack/docker-compose/app/docker-compose.yml: `version` is obsolete 
ws-app-services  | AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 172.19.0.10. Set the 'ServerName' directive globally to suppress this message
ws-app-services  | AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 172.19.0.10. Set the 'ServerName' directive globally to suppress this message
mikaelz commented 7 months ago

Removing those WARN rows didn't help

folkertvanheusden commented 4 months ago

I don't have the colorscheme monolog?

mikaelz commented 4 months ago

Tried without monolog and the same

multitail: /home/mike/.cache/yay/multitail/src/multitail-7.1.2/utils.c:366: amount_to_str: Assertion `amount >= 0' failed.
[1]    659760 IOT instruction (core dumped)  multitail -l 'docker-compose logs --no-color -t -f ws-app-services
systemd-coredump[671037]: [🡕] Process 671002 (multitail) of user 1000 dumped core.

                                                  Stack trace of thread 671002:
                                                  #0  0x000079678f0cce44 n/a (libc.so.6 + 0x94e44)
                                                  #1  0x000079678f074a30 raise (libc.so.6 + 0x3ca30)
                                                  #2  0x000079678f05c4c3 abort (libc.so.6 + 0x244c3)
                                                  #3  0x000079678f05c3df n/a (libc.so.6 + 0x243df)
                                                  #4  0x000079678f06cc67 __assert_fail (libc.so.6 + 0x34c67)
                                                  #5  0x00005e0197c0a899 n/a (multitail + 0x1d899)
                                                  #6  0x00005e0197bfcb2f n/a (multitail + 0xfb2f)
                                                  #7  0x00005e0197c0364f n/a (multitail + 0x1664f)
                                                  #8  0x00005e0197c05f2f n/a (multitail + 0x18f2f)
                                                  #9  0x00005e0197bf175a n/a (multitail + 0x475a)
                                                  #10 0x000079678f05dc88 n/a (libc.so.6 + 0x25c88)
                                                  #11 0x000079678f05dd4c __libc_start_main (libc.so.6 + 0x25d4c)
                                                  #12 0x00005e0197bf1d05 n/a (multitail + 0x4d05)
                                                  ELF object binary architecture: AMD x86-64
folkertvanheusden commented 4 months ago

Can't reproduce with the snippet of logging you gave me.

leonidx86 commented 4 months ago

I'm getting the same error on version 6.5.0 with logs from Keycloak (right on start). What's interesting is that it happens randomly. Sometimes it crashes, sometimes it's not. On other logs that I'm monitoring it does not crash.

I've tested with an empty config file, but it does not matter.

multitail -l "./keycloak/bin/kc.sh start-dev"
multitail --config empty.conf -l "./keycloak/bin/kc.sh start-dev"

There is no major difference in logs when it crashes and when it's not. They look almost the same up to the crash moment.

Crash:

2024-06-24 12:23:45,235 INFO  [org.infinispan.CONTAINER] (ForkJoinPool.commonPool-worker-1) ISPN000556: Starting user marshaller 'org.infinispan.jboss.marshalling.core.JBossUserMarshaller'
2024-06-24 12:23:48,836 INFO  [org.keycloak.connections.infinispan.DefaultInfinispanConnectionProviderFactory] (main) Node name: node_256350, Site name: null
2024-06-24 12:23:48,838 INFO  [org.keycloak.broker.provider.AbstractIdentityProviderMapper] (main) Registering class org.keycloak.broker.provider.mappersync.ConfigSyncEventListener
multitail: utils.c:366: amount_to_str: Assertion `amount >= 0' failed.

No crash:

2024-06-24 12:37:28,689 INFO  [org.infinispan.CONTAINER] (ForkJoinPool.commonPool-worker-1) ISPN000556: Starting user marshaller 'org.infinispan.jboss.marshalling.core.JBossUserMarshaller'
2024-06-24 12:37:32,284 INFO  [org.keycloak.connections.infinispan.DefaultInfinispanConnectionProviderFactory] (main) Node name: node_300, Site name: null
2024-06-24 12:37:32,287 INFO  [org.keycloak.broker.provider.AbstractIdentityProviderMapper] (main) Registering class org.keycloak.broker.provider.mappersync.ConfigSyncEventListener
2024-06-24 12:37:32,748 INFO  [io.quarkus] (main) Keycloak 25.0.1 on JVM (powered by Quarkus 3.8.5) started in 5.646s. Listening on: http://0.0.0.0:8080. Management interface listening on http://0.0.0.0:9000.
2024-06-24 12:37:32,748 INFO  [io.quarkus] (main) Profile dev activated.
2024-06-24 12:37:32,748 INFO  [io.quarkus] (main) Installed features: [agroal, cdi, hibernate-orm, jdbc-h2, keycloak, logging-gelf, narayana-jta, reactive-routes, resteasy-reactive, resteasy-reactive-jackson, smallrye-context-propagation, vertx]
2024-06-24 12:37:32,750 WARN  [org.keycloak.quarkus.runtime.KeycloakMain] (main) Running the server in development mode. DO NOT use this configuration in production.
folkertvanheusden commented 4 months ago

Is multitail installed from source?

Also, could you please do: 'coredumpctl debug' and then 'bt'. Hopefully the stacktrace of gdb is more useful than the build-in one,. I can see where it crashes (well, aborst) but I would like to see who calls it. Apparently some byte-amount becomes negative.

On Mon, Jun 24, 2024 at 11:52 AM leonidx86 @.***> wrote:

I'm getting the same error on version 6.5.0 with logs from Keycloak https://www.keycloak.org/ (right on start). What's interesting is that it happens randomly. Sometimes it crashes, sometimes it's not. On other logs that I'm monitoring it does not crash.

I've tested with an empty config file, but it does not matter.

multitail -l "./keycloak/bin/kc.sh start-dev" multitail --config empty.conf -l "./keycloak/bin/kc.sh start-dev"

There is no major difference in logs when it crashes and when it's not. They look almost the same up to the crash moment.

Crash:

2024-06-24 12:23:45,235 INFO [org.infinispan.CONTAINER] (ForkJoinPool.commonPool-worker-1) ISPN000556: Starting user marshaller 'org.infinispan.jboss.marshalling.core.JBossUserMarshaller' 2024-06-24 12:23:48,836 INFO [org.keycloak.connections.infinispan.DefaultInfinispanConnectionProviderFactory] (main) Node name: node_256350, Site name: null 2024-06-24 12:23:48,838 INFO [org.keycloak.broker.provider.AbstractIdentityProviderMapper] (main) Registering class org.keycloak.broker.provider.mappersync.ConfigSyncEventListener multitail: utils.c:366: amount_to_str: Assertion `amount >= 0' failed.

No crash:

2024-06-24 12:37:28,689 INFO [org.infinispan.CONTAINER] (ForkJoinPool.commonPool-worker-1) ISPN000556: Starting user marshaller 'org.infinispan.jboss.marshalling.core.JBossUserMarshaller' 2024-06-24 12:37:32,284 INFO [org.keycloak.connections.infinispan.DefaultInfinispanConnectionProviderFactory] (main) Node name: node_300, Site name: null 2024-06-24 12:37:32,287 INFO [org.keycloak.broker.provider.AbstractIdentityProviderMapper] (main) Registering class org.keycloak.broker.provider.mappersync.ConfigSyncEventListener 2024-06-24 12:37:32,748 INFO [io.quarkus] (main) Keycloak 25.0.1 on JVM (powered by Quarkus 3.8.5) started in 5.646s. Listening on: http://0.0.0.0:8080. Management interface listening on http://0.0.0.0:9000. 2024-06-24 12:37:32,748 INFO [io.quarkus] (main) Profile dev activated. 2024-06-24 12:37:32,748 INFO [io.quarkus] (main) Installed features: [agroal, cdi, hibernate-orm, jdbc-h2, keycloak, logging-gelf, narayana-jta, reactive-routes, resteasy-reactive, resteasy-reactive-jackson, smallrye-context-propagation, vertx] 2024-06-24 12:37:32,750 WARN [org.keycloak.quarkus.runtime.KeycloakMain] (main) Running the server in development mode. DO NOT use this configuration in production.

— Reply to this email directly, view it on GitHub https://github.com/folkertvanheusden/multitail/issues/35#issuecomment-2186085540, or unsubscribe https://github.com/notifications/unsubscribe-auth/AUN5IW2PRCSJ2F3DTPME4MTZI7T3VAVCNFSM6AAAAABFYQDGNKVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDCOBWGA4DKNJUGA . You are receiving this because you commented.Message ID: @.***>

mikaelz commented 4 months ago 
$ coredumpctl debug
           PID: 800078 (multitail)
           UID: 1000 (mike)
           GID: 984 (users)
        Signal: 6 (ABRT)
     Timestamp: Tue 2024-06-25 08:16:22 CEST (24s ago)
  Command Line: multitail -cS monolog -l $'docker-compose logs --no-color -t -f ws-app-services'
    Executable: /usr/bin/multitail
 Control Group: /user.slice/user-1000.slice/session-1.scope
          Unit: session-1.scope
         Slice: user-1000.slice
       Session: 1
     Owner UID: 1000 (mike)
       Boot ID: 0a1d78ab7b894e66b26f0d0f16553fb4
    Machine ID: a1b21d7ee69445ef82343d227951ca86
      Hostname: mike-pc
       Storage: /var/lib/systemd/coredump/core.multitail.1000.0a1d78ab7b894e66b26f0d0f16553fb4.800078.1719296182000000.zst (present)
  Size on Disk: 686.2K
       Message: Process 800078 (multitail) of user 1000 dumped core.

                Stack trace of thread 800078:
                #0  0x000070f079108e44 n/a (libc.so.6 + 0x94e44)
                #1  0x000070f0790b0a30 raise (libc.so.6 + 0x3ca30)
                #2  0x000070f0790984c3 abort (libc.so.6 + 0x244c3)
                #3  0x000070f0790983df n/a (libc.so.6 + 0x243df)
                #4  0x000070f0790a8c67 __assert_fail (libc.so.6 + 0x34c67)
                #5  0x000057f923f7d899 n/a (multitail + 0x1d899)
                #6  0x000057f923f6fb2f n/a (multitail + 0xfb2f)
                #7  0x000057f923f7664f n/a (multitail + 0x1664f)
                #8  0x000057f923f78f2f n/a (multitail + 0x18f2f)
                #9  0x000057f923f6475a n/a (multitail + 0x475a)
                #10 0x000070f079099c88 n/a (libc.so.6 + 0x25c88)
                #11 0x000070f079099d4c __libc_start_main (libc.so.6 + 0x25d4c)
                #12 0x000057f923f64d05 n/a (multitail + 0x4d05)
                ELF object binary architecture: AMD x86-64

GNU gdb (GDB) 14.2
Copyright (C) 2023 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-pc-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /usr/bin/multitail...

This GDB supports auto-downloading debuginfo from the following URLs:
  <https://debuginfod.archlinux.org>
Enable debuginfod for this session? (y or [n]) y
Debuginfod has been enabled.
To make this setting permanent, add 'set debuginfod enabled on' to .gdbinit.
(No debugging symbols found in /usr/bin/multitail)                                                                                                                                                                                             
[New LWP 800078]
Downloading separate debug info for system-supplied DSO at 0x70f0793e8000                                                                                                                                                                      
[Thread debugging using libthread_db enabled]                                                                                                                                                                                                  
Using host libthread_db library "/usr/lib/libthread_db.so.1".
Core was generated by `multitail -cS monolog -l docker-compose logs --no-color -t -f ws-app-services'.
Program terminated with signal SIGABRT, Aborted.
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at pthread_kill.c:44
44        return INTERNAL_SYSCALL_ERROR_P (ret) ? INTERNAL_SYSCALL_ERRNO (ret) : 0;                                                                                                                                                        
(gdb) bt
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at pthread_kill.c:44
#1  0x000070f079108eb3 in __pthread_kill_internal (threadid=<optimized out>, signo=6) at pthread_kill.c:78
#2  0x000070f0790b0a30 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#3  0x000070f0790984c3 in __GI_abort () at abort.c:79
#4  0x000070f0790983df in __assert_fail_base (fmt=0x70f079223b68 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x57f923f8c343 "amount >= 0", 
    file=file@entry=0x57f923f8da20 "/home/mike/.cache/yay/multitail/src/multitail-7.1.2/utils.c", line=line@entry=366, function=function@entry=0x57f923f96758 "amount_to_str") at assert.c:94
#5  0x000070f0790a8c67 in __assert_fail (assertion=0x57f923f8c343 "amount >= 0", file=0x57f923f8da20 "/home/mike/.cache/yay/multitail/src/multitail-7.1.2/utils.c", line=366, function=0x57f923f96758 "amount_to_str") at assert.c:103
#6  0x000057f923f7d899 in ?? ()
#7  0x000057f923f6fb2f in ?? ()
#8  0x000057f923f7664f in ?? ()
#9  0x000057f923f78f2f in ?? ()
#10 0x000057f923f6475a in ?? ()
#11 0x000070f079099c88 in __libc_start_call_main (main=main@entry=0x57f923f64020, argc=argc@entry=5, argv=argv@entry=0x7ffc4e6ee6f8) at ../sysdeps/nptl/libc_start_call_main.h:58
#12 0x000070f079099d4c in __libc_start_main_impl (main=0x57f923f64020, argc=5, argv=0x7ffc4e6ee6f8, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7ffc4e6ee6e8) at ../csu/libc-start.c:360
#13 0x000057f923f64d05 in ?? ()
leonidx86 commented 4 months ago

I get similar result with a little more info (#6, #7, #8).

Core was generated by `multitail -l ./keycloak/bin/kc.sh start-dev'.
Program terminated with signal SIGABRT, Aborted.
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at pthread_kill.c:44
44        return INTERNAL_SYSCALL_ERROR_P (ret) ? INTERNAL_SYSCALL_ERRNO (ret) : 0;
Missing separate debuginfos, use: zypper install libncurses6-debuginfo-6.5.20240601-38.1.x86_64
(gdb) bt
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at pthread_kill.c:44
#1  0x00007fd16c294a63 in __pthread_kill_internal (signo=6, threadid=<optimized out>) at pthread_kill.c:78
#2  0x00007fd16c241176 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#3  0x00007fd16c228917 in __GI_abort () at abort.c:79
#4  0x00007fd16c22882b in __assert_fail_base (fmt=0x7fd16c3b4c18 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", 
    assertion=assertion@entry=0x556d94ab504f "amount >= 0", file=file@entry=0x556d94ab5004 "utils.c", line=line@entry=366, 
    function=function@entry=0x556d94ac0cb8 <__PRETTY_FUNCTION__.17> "amount_to_str") at assert.c:94
#5  0x00007fd16c239076 in __assert_fail (assertion=assertion@entry=0x556d94ab504f "amount >= 0", file=file@entry=0x556d94ab5004 "utils.c", 
    line=line@entry=366, function=function@entry=0x556d94ac0cb8 <__PRETTY_FUNCTION__.17> "amount_to_str") at assert.c:103
#6  0x0000556d94a8ada1 in amount_to_str (amount=-2133434368) at /usr/src/debug/multitail-6.5.0/utils.c:366
#7  0x0000556d94a9746e in update_statusline (status=0x556d9a66e9a0, win_nr=<optimized out>, cur=0x556d9a244700)
    at /usr/src/debug/multitail-6.5.0/mt.c:1420
#8  0x0000556d94aae56f in update_statusline (cur=0x556d9a244700, win_nr=<optimized out>, status=<optimized out>)
    at /usr/src/debug/multitail-6.5.0/mt.c:1356
#9  wait_for_keypress.constprop.0 (what_help=0, popup=0x0, cursor_shift=0 '\000', max_wait=0) at /usr/src/debug/multitail-6.5.0/mt.c:3649
#10 0x0000556d94a92460 in main_loop () at /usr/src/debug/multitail-6.5.0/mt.c:2452
#11 0x0000556d94a8a2b1 in main (argc=<optimized out>, argv=<optimized out>) at /usr/src/debug/multitail-6.5.0/mt.c:2841
folkertvanheusden commented 4 months ago

I don't understand this, this bug was fixed in 2015. For now, try removing the assert-line. You may see negative values, but only for a short period of time.

On Tue, Jun 25, 2024 at 8:47 AM leonidx86 @.***> wrote:

I get similar result with a little more info (#6, #7, #8).

Core was generated by `multitail -l ./keycloak/bin/kc.sh start-dev'. Program terminated with signal SIGABRT, Aborted.

0 __pthread_kill_implementation (threadid=, @.=6, @.=0) at pthread_kill.c:44

44 return INTERNAL_SYSCALL_ERROR_P (ret) ? INTERNAL_SYSCALL_ERRNO (ret) : 0; Missing separate debuginfos, use: zypper install libncurses6-debuginfo-6.5.20240601-38.1.x86_64 (gdb) bt

0 __pthread_kill_implementation (threadid=, @.=6, @.=0) at pthread_kill.c:44

1 0x00007fd16c294a63 in __pthread_kill_internal (signo=6, threadid=) at pthread_kill.c:78

2 0x00007fd16c241176 in __GI_raise @.***=6) at ../sysdeps/posix/raise.c:26

3 0x00007fd16c228917 in __GI_abort () at abort.c:79

4 0x00007fd16c22882b in __assert_fail_base (fmt=0x7fd16c3b4c18 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n",

***@***.***=0x556d94ab504f "amount >= 0", ***@***.***=0x556d94ab5004 "utils.c", ***@***.***=366,
***@***.***=0x556d94ac0cb8 <__PRETTY_FUNCTION__.17> "amount_to_str") at assert.c:94

5 0x00007fd16c239076 in __assert_fail @.=0x556d94ab504f "amount >= 0", @.=0x556d94ab5004 "utils.c",

***@***.***=366, ***@***.***=0x556d94ac0cb8 <__PRETTY_FUNCTION__.17> "amount_to_str") at assert.c:103

6 0x0000556d94a8ada1 in amount_to_str (amount=-2133434368) at /usr/src/debug/multitail-6.5.0/utils.c:366

7 0x0000556d94a9746e in update_statusline (status=0x556d9a66e9a0, win_nr=, cur=0x556d9a244700)

at /usr/src/debug/multitail-6.5.0/mt.c:1420

8 0x0000556d94aae56f in update_statusline (cur=0x556d9a244700, win_nr=, status=)

at /usr/src/debug/multitail-6.5.0/mt.c:1356

9 wait_for_keypress.constprop.0 (what_help=0, popup=0x0, cursor_shift=0 '\000', max_wait=0) at /usr/src/debug/multitail-6.5.0/mt.c:3649

10 0x0000556d94a92460 in main_loop () at /usr/src/debug/multitail-6.5.0/mt.c:2452

11 0x0000556d94a8a2b1 in main (argc=, argv=) at /usr/src/debug/multitail-6.5.0/mt.c:2841

— Reply to this email directly, view it on GitHub https://github.com/folkertvanheusden/multitail/issues/35#issuecomment-2188109079, or unsubscribe https://github.com/notifications/unsubscribe-auth/AUN5IW3HFHKYIGEHXKV7R2DZJEG6DAVCNFSM6AAAAABFYQDGNKVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDCOBYGEYDSMBXHE . You are receiving this because you commented.Message ID: @.***>

leonidx86 commented 4 months ago

Removed assert, and as you've said I see negative VMsize value. In case of Keycloak it's random. Sometimes it settles on positive value, like 2GB (VMsize), and sometimes negative, like -2065 (VMsize).

folkertvanheusden commented 4 months ago

I think it happens when a process restarts. Fwiw I removed the assert and released 7.1.3

On Tue, Jun 25, 2024 at 10:09 AM leonidx86 @.***> wrote:

Removed assert, and as you've said I see negative VMsize value. In case of Keycloak it's random. Sometimes it settles on positive value, like 2GB (VMsize), and sometimes negative, like -2065 (VMsize).

— Reply to this email directly, view it on GitHub https://github.com/folkertvanheusden/multitail/issues/35#issuecomment-2188252659, or unsubscribe https://github.com/notifications/unsubscribe-auth/AUN5IW2OCDRQDTA3LEQVL33ZJEQRVAVCNFSM6AAAAABFYQDGNKVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDCOBYGI2TENRVHE . You are receiving this because you commented.Message ID: @.***>

mikaelz commented 4 months ago

Awesome, thank you. Now it works