[Freeciv-Dev] [bug #21083] verbose logging ("-d 3") + log_error() => server hang due to recursive logging

[Marko Lindqvist]

Update of bug #21083 (project freeciv):

 Planned Release: => 2.6.0, 3.0.0   


___

Reply to this item at:

  

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


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

[Freeciv-Dev] [bug #21083] verbose logging ("-d 3") + log_error() => server hang due to recursive logging

[pepeto]

Update of bug #21083 (project freeciv):

  Status:  Ready For Test => None   

___

Follow-up Comment #6:

You are right, my patch wouldn't work.

Also, if we don't want to lose messages on recursion case. Maybe should the
whole log should be a thread?


___

Reply to this item at:

  

___
  Message posté via/par Gna!
  http://gna.org/


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

[Freeciv-Dev] [bug #21083] verbose logging ("-d 3") + log_error() => server hang due to recursive logging

[Jacob Nevins]

Follow-up Comment #2, bug #21083 (project freeciv):

See also bug #21683.

> Maybe the lock is being kept longer than necessary? 
> Why the logfile would need to be locked when one is doing the 
> network part?
The lock is in log_real() around the call to log_write(). log_write() does two
things: writes to the file, and calls log_callback, which in this case is
con_handle_log(), which sends stuff to the network, causing recursive hilarity
to ensue.

It feels like some of the things in con_handle_log() don't want to be called
by multiple threads simultaneously, though.

___

Reply to this item at:

  

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


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

[Freeciv-Dev] [bug #21083] verbose logging ("-d 3") + log_error() => server hang due to recursive logging

[Marko Lindqvist]

Follow-up Comment #1, bug #21083 (project freeciv):

Maybe the lock is being kept longer than necessary? Why the  logfile would
need to be locked when one is doing the network part?

___

Reply to this item at:

  

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


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

[Freeciv-Dev] [bug #21083] verbose logging ("-d 3") + log_error() => server hang due to recursive logging

[Jacob Nevins]

URL:
  

 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  0x7fe7fd750065 in _L_lock_858 ()
   from /lib/x86_64-linux-gnu/libpthread.so.0
No symbol table info available.
#2  0x7fe7fd74feba in __pthread_mutex_lock (mutex=0xab45e0)
at pthread_mutex_lock.c:61
__PRETTY_FUNCTION__ = "__pthread_mutex_lock"
type = 11224544
#3  0x005eed1b 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' , '\000' 
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' , "\032\000\000\000\004\000\000\000\002", '\000'
"\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' ,
"\002\000\000\000\000\000\000\240\272(^\377\177\000\000\220"...
fs = 
#4  0x005ebb75 in backtrace_log (level=LOG_VERBOSE, 
print_from_where=, where=, 
msg=) at fcbacktrace.c:100
No locals.
#5  0x005ef4fb 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=, 
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' ,
"#115511\000\004", '\000' , "(^\377\177", '\000' , " `\335\365\347\177", '\000' ,
"о(^\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' ,
"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'
,
"`\\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' ,
"\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  0x005ef5cd in do_log (file=, 
function=, line=, 
print_from_where=, level=, 
message=) at log.c:477
args = {{gp_offset = 48, fp_offset = 48, 
overflow_arg_area = 0x7fff5e28bfd0, 
reg_save_area = 0x7fff5e28bf10}}
#7  0x005629f4 in send_packet_chat_msg_100 (pc=0x8fd6a0, 
packet=0x7fff5e28d040) at packets_gen.c:7122
real_packet = 0x7fff5e28d040
fields = {vec = ""}
old = 
differ = 
hash = 0x178ad78
different = 0
bu