URL:
  <http://gna.org/bugs/?21083>

                 Summary: verbose logging ("-d 3") + log_error() => server
hang due to recursive logging
                 Project: Freeciv
            Submitted by: jtn
            Submitted on: Sat Aug 31 12:48:37 2013
                Category: None
                Severity: 3 - Normal
                Priority: 5 - Normal
                  Status: None
             Assigned to: None
        Originator Email: 
             Open/Closed: Open
                 Release: S2_4 r23235
         Discussion Lock: Any
        Operating System: None
         Planned Release: 

    _______________________________________________________

Details:

Server hung consuming no CPU when I was testing an error case, but only when I
had both "-d 3" and "-l foo.log" on the server command line.

I think the problem is that when log_error() is called on the server, it
provokes a chat message to send to clients in the depths of log_real(); with
"-d 3" the resulting network traffic is itself logged, leading to a deadlock
waiting for a lock on the logfile. (I think.)

This is similar to bug #20721 but the fix will be more involved.


#0  __lll_lock_wait ()
    at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:132
No locals.
#1  0x00007fe7fd750065 in _L_lock_858 ()
   from /lib/x86_64-linux-gnu/libpthread.so.0
No symbol table info available.
#2  0x00007fe7fd74feba in __pthread_mutex_lock (mutex=0xab45e0)
    at pthread_mutex_lock.c:61
        __PRETTY_FUNCTION__ = "__pthread_mutex_lock"
        type = 11224544
#3  0x00000000005eed1b in log_real (level=LOG_VERBOSE, print_from_where=false,

    where=0x7fff5e28baa0 "in send_packet_chat_msg_100() [packets_gen.c::7122]:
", msg=0x7fff5e28bca0 "packet_chat_msg_100: sending info about ()") at
log.c:400
        last_msg = "Map has no land, so cannot assign start positions!\000e:
0).\000 jtn\000", '0' <repeats 44 times>, '\000' <repeats 404 times>
        repeated = 0
        next = 2
        prev = 0
        prev_level = LOG_ERROR
        buf =
"\240\272(^\377\177\000\000\240\272(^\377\177\000\000\240\272(^\377\177\000\000պ(^\377\177\000\000\237\274(^\377\177\000\000\240\272(^\377\177\000\000\237\274(^\377\177",
'\000' <repeats 42 times>, "\032\000\000\000\004\000\000\000\002", '\000'
<repeats 11 times>"\377, \377\377\377\000\000\000\000\000\000\000\000
tarting\020\271(^\377\177\000\000\240\274(^\377\177\000\000\000\000\000\000\000\000\000\000\001\000\000\000\000\000\000\000\370\276(^\377\177\000\000\377\377\377\377\000\000\000\000\bbh\000\000\000\000\000\240\274(^\377\177\000\000\240\257\253\374\347\177\000\000\000\000\000\000\000\000\000\000\240\274(^\377\177\000\000\240\274(^\377\177\000\000\240\274(^\377\177\000\000\240\274(^\377\177\000\000ʼ(^\377\177\000\000\237\276(^\377\177\000\000\240\274(^\377\177\000\000\237\276(^\377\177",
'\000' <repeats 19 times>,
"\002\000\000\000\000\000\000\240\272(^\377\177\000\000\220"...
        fs = <optimised out>
#4  0x00000000005ebb75 in backtrace_log (level=LOG_VERBOSE, 
    print_from_where=<optimised out>, where=<optimised out>, 
    msg=<optimised out>) at fcbacktrace.c:100
No locals.
#5  0x00000000005ef4fb in vdo_log (file=0x6805f8 "packets_gen.c", 
    function=0x694390 "send_packet_chat_msg_100", line=7122, 
    print_from_where=false, level=LOG_VERBOSE, message=<optimised out>, 
    args=0x7fff5e28bef8) at log.c:377
        buf_where = "in send_packet_chat_msg_100() [packets_gen.c::7122]:
\000\000\000\060\000\000\000\060\000\000\000P\274(^\377\177\000\000P\273(^\377\177\000\000\213\274(^\377\177\000\000
\341\364\000\000\000\000\000F00", '\000' <repeats 25 times>,
"#115511\000\004", '\000' <repeats 13 times>, "(^\377\177", '\000' <repeats 18
times>, " `\335\365\347\177", '\000' <repeats 18 times>,
"о(^\377\177\000\000\001\000\000\000\377\177\000\000\000\000\000\000\000\000\000\000\030\277(^\377\177\000\000\000\000\000\000\377\177\000\000
Ы\374\347\177\000\000\000\001", '\000' <repeats 14 times>,
"A\000\000\000\377"...
        buf_msg = "packet_chat_msg_100: sending info about
()\000\374\347\177\000\000\374\377\377\377\377\377\377\377u\006j", '\000'
<repeats 21 times>,
"`\\u\375\347\177\000\000\000\276(^\377\177\000\000\000\000\000\000\377\177\000\000\000\000\000\000\000\000\000\000\030\000\000\000\060\000\000\000\360\277(^\377\177\000\000\060\277(^\377\177\000\000\260\303(^\377\177\000\000X\305(^\377\177\000\000g\006j\000\000\000\000\000%\000\000\000\000\000\000\000\314\312t\374\347\177\000\000\001\200\255\373\060\060\060\060v\006j",
'\000' <repeats 13 times>,
"\003\000\000\000\000\000\000\000\207\271(^\377\177\000\000\070\277(^\377\177\000\000\177\000\000\000\000\000\000\000^\001x\374\347\177\000\000\030\000\000\000\060\000\000\000
\301(^\377\177\000\000"...
#6  0x00000000005ef5cd in do_log (file=<optimised out>, 
    function=<optimised out>, line=<optimised out>, 
    print_from_where=<optimised out>, level=<optimised out>, 
    message=<optimised out>) at log.c:477
        args = {{gp_offset = 48, fp_offset = 48, 
            overflow_arg_area = 0x7fff5e28bfd0, 
            reg_save_area = 0x7fff5e28bf10}}
#7  0x00000000005629f4 in send_packet_chat_msg_100 (pc=0x8fd6a0, 
    packet=0x7fff5e28d040) at packets_gen.c:7122
        real_packet = 0x7fff5e28d040
        fields = {vec = ""}
        old = <optimised out>
        differ = <optimised out>
        hash = 0x178ad78
        different = 0
        buffer =
"\000\000\031\000\000\000\000\000\270\342_\000\000\000\000\000\000\037\254\374\347\177\000\000\060\310(^\377\177\000\000\003\000\000\000\000\000\000\000\200\000\000\000\000\000\000\000p\301(^\377\177\000\000\020{x\001",
'\000' <repeats 12 times>,
"0\306(^\377\177\000\000\003\000\000\000\000\000\000\000\270\342_\000\000\000\000\000\302\000\000\000\000\000\000\000\060\310(^\377\177\000\000\003\000\000\000\000\000\000\000\222\343_",
'\000' <repeats 13 times>, "
\000\000\000\060\000\000\000p\301(^\377\177\000\000\000·\335=$;\233\000\037\062\060\063\061\000\000(\301(^\377\177\000\000\003\000\000\000\000\000\000\000p\301(^\377\177\000\000\060\306(^\377\177\000\000\060\310(^\377\177\000\000\000\000\000\000\000\000\000\000\060\306(^\377\177\000\000\003\000\000\000\000\000\000\000\226\307{\374\347\177\000\000\060\310(^\377"...
        dout = {dest = 0x7fff5e28c010, dest_size = 4096, used = 3, 
          current = 3, too_short = false}
        __FUNCTION__ = "send_packet_chat_msg_100"
#8  0x000000000043156b in notify_conn_packet (dest=<optimised out>, 
    packet=0x7fff5e28d6e0) at notify.c:225
        pconn_iter = 0x0
        pconn = 0x8fd6a0
        real_packet = {
          message = "[c fg=\"#FF0000\"]The server couldn't allocate starting
positions.[/c]\000\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000"...,
tile = -1, 
          event = E_LOG_ERROR, conn_id = -1}
        tile = -1
        ptile = 0x0
        __FUNCTION__ = "notify_conn_packet"
#9  0x0000000000431e86 in notify_conn (dest=0x0, ptile=<optimised out>, 
    event=<optimised out>, color=..., format=<optimised out>) at notify.c:245
        genmsg = {
          message = "[c fg=\"#FF0000\"]The server couldn't allocate starting
positions.[/c]\000\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000>\000\000\000"...,
tile = -1, 
          event = E_LOG_ERROR, conn_id = -1}
        args = {{gp_offset = 48, fp_offset = 48, 
            overflow_arg_area = 0x7fff5e28ddc8, 
            reg_save_area = 0x7fff5e28dd00}}
#10 0x0000000000431388 in con_handle_log (level=LOG_ERROR, 
    message=0x7fff5e28e4c0 "The server couldn't allocate starting positions.",

    file_too=true) at console.c:59
        __FUNCTION__ = "con_handle_log"
#11 0x00000000005eebd6 in log_write (fs=0x17a5860, level=LOG_ERROR, 
    print_from_where=false, 
    where=0x7fff5e28e2c0 "in map_fractal_generate() [mapgen.c::1467]: ", 
    message=0x7fff5e28e4c0 "The server couldn't allocate starting
positions.")
    at log.c:350
No locals.
#12 0x00000000005eed93 in log_real (level=LOG_ERROR, 
    print_from_where=<optimised out>, 
    where=0x7fff5e28e2c0 "in map_fractal_generate() [mapgen.c::1467]: ", 
    msg=0x7fff5e28e4c0 "The server couldn't allocate starting positions.")
    at log.c:451
        last_msg = "Map has no land, so cannot assign start positions!\000e:
0).\000 jtn\000", '0' <repeats 44 times>, '\000' <repeats 404 times>
        repeated = 0
        next = 2
        prev = 0
        prev_level = LOG_ERROR
        buf =
"\300\342(^\377\177\000\000\300\342(^\377\177\000\000\300\342(^\377\177\000\000\354\342(^\377\177\000\000\277\344(^\377\177\000\000\300\342(^\377\177\000\000\277\344(^\377\177",
'\000' <repeats 42 times>"\231,
Zd\000\004\000\000\000\222\343_\000\000\000\000\000\000\000(^\377\177\000\000\000\000\000\000\000\000\000\000\260\341(^\377\177\000\000\060\341(^\377\177\000\000\300\344(^\377\177\000\000\000\000\000\000\000\000\000\000\001\000\000\000\000\000\000\000\030\347(^\377\177\000\000\377\377\377\377\000\000\000\000\310Sd\000\000\000\000\000\300\344(^\377\177\000\000\240\257\253\374\347\177\000\000\000\000\000\000\000\000\000\000\300\344(^\377\177\000\000\300\344(^\377\177\000\000\300\344(^\377\177\000\000\300\344(^\377\177\000\000\360\344(^\377\177\000\000\277\346(^\377\177\000\000\300\344(^\377\177\000\000\277\346(^\377\177",
'\000' <repeats 19 times>,
"\002\000\000\000\000\000\000\300\342(^\377\177\000\000\000Td", '\000'
<repeats 13 times>...
        fs = 0x17a5860
#13 0x00000000005ebb75 in backtrace_log (level=LOG_ERROR, 
    print_from_where=<optimised out>, where=<optimised out>, 
    msg=<optimised out>) at fcbacktrace.c:100
No locals.
#14 0x00000000005ef4fb in vdo_log (file=0x6447fe "mapgen.c", 
    function=0x645400 "map_fractal_generate", line=1467, 
    print_from_where=false, level=LOG_ERROR, message=<optimised out>, 
    args=0x7fff5e28e718) at log.c:377
        buf_where = "in map_fractal_generate() [mapgen.c::1467]:
\000\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000Map
has 0 continents and 1
oceans\000\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000\356\002\000\000,\003\000\000,\003\000\000,\003\000\000"...
        buf_msg = "The server couldn't allocate starting
positions.\000\000\000\000\000\000\000\000\240\346(^\377\177\000\000\000\000\000\000\000\000\000\000xzs\374\347\177\000\000m\236c\000\000\000\000\000\030\000\000\000\000\000\000\000\310\003j\000\000\000\000\000\030\000\000\000\000\000\000\000\001\000\000\000\000\000\000\000\000·\335=$;\233\340~\244\001\000\000\000\000\002\000\000\000\000\000\000\000\200\346(^\377\177\000\000@ޫ\374\347\177\000\000\000\000\000\000\000\000\000\000\315\365^\000\000\000\000\000,\000\000\000\000\000\000\000\200\360\364",
'\000' <repeats 29 times>,
"\023\016)^\377\177\000\000p\346(^\377\177\000\000\200\360\364\000\000\000\000\000\240\346(^\377\177\000\000\200\346(^\377\177"...
#15 0x00000000005ef5cd in do_log (file=<optimised out>, 
    function=<optimised out>, line=<optimised out>, 
    print_from_where=<optimised out>, level=<optimised out>, 
    message=<optimised out>) at log.c:477
        args = {{gp_offset = 48, fp_offset = 48, 
            overflow_arg_area = 0x7fff5e28e7f0, 
            reg_save_area = 0x7fff5e28e730}}
#16 0x0000000000467153 in map_fractal_generate (autosize=<optimised out>, 
    initial_unit=0xa95420) at mapgen.c:1467
        success = <optimised out>
        mode = MAPSTARTPOS_DEFAULT
        rstate = {v = {103102502, 1409254898, 1944169296, 2804496665, 
            2998080550, 4183393959, 2909709582, 385378918, 1069445921, 
            304201768, 4253748078, 3024458605, 4178032850, 1893632976, 
            3227567073, 1734928590, 878483358, 660178426, 2093945540, 
            3673391736, 1513418478, 3584405094, 2520646403, 2372982132, 
            3622728577, 3690322443, 2300839067, 3213984506, 2047313983, 
            1687599531, 2422934511, 3702107368, 1114142073, 2230157446, 
            1881433394, 1510481788, 3476243356, 455558851, 1840960877, 
            4157258903, 2815956827, 394573956, 4065583695, 3252120852, 
            4180830543, 1173261078, 415099247, 3926106845, 1542313477, 
            2882411107, 1496686372, 3423241828, 1538049311, 3534465973, 
            3210669957, 3499232209}, j = 47, k = 22, x = 46, is_init = true}
        __FUNCTION__ = "map_fractal_generate"
#17 0x00000000004379eb in srv_ready () at srv_main.c:2542
        i = <optimised out>
        utype = <optimised out>
        sucount = 5
        retry_ok = true
        max = 2
        created = <optimised out>
#18 srv_main () at srv_main.c:2769
        __FUNCTION__ = "srv_main"
#19 0x000000000043066a in main (argc=<optimised out>, argv=0x7fff5e28ec98)
    at civserver.c:453
        inx = 7
        showhelp = <optimised out>
        showvers = <optimised out>
        option = <optimised out>
        __FUNCTION__ = "main"





    _______________________________________________________

Reply to this item at:

  <http://gna.org/bugs/?21083>

_______________________________________________
  Message sent via/by Gna!
  http://gna.org/


_______________________________________________
Freeciv-dev mailing list
Freeciv-dev@gna.org
https://mail.gna.org/listinfo/freeciv-dev

Reply via email to