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
[email protected]
https://mail.gna.org/listinfo/freeciv-dev
