Sys_error("Mutex.unlock: Operation not permitted") on double call to message function

[mjambon]

The following code raises the Sys_error("Mutex.unlock: Operation not permitted") exception as of logs.0.9.0:

Logs_threaded.enable ();;
Logs.set_reporter (Logs_fmt.reporter ());;
Logs.set_level (Some Info);;
Logs.info (fun m -> m ""; m "");;

$ ocamlfind opt -package logs,logs.fmt,logs.threaded -linkpkg -o logs_mutex logs_mutex.ml
$ ./logs_mutex 
logs_mutex: [INFO] 
logs_mutex: [INFO] 
Fatal error: exception Sys_error("Mutex.unlock: Operation not permitted")

A simple workaround is to avoid calling the m function twice and instead call Logs.info twice:

Logs.info (fun m -> m "");;
Logs.info (fun m -> m "");;

[dbuenzli]

Interesting use of the API :–) I don't think it was ever meant to be used that way, one API call represent one logging operation and a single call to m. But as a matter of fact you can, maybe this should be mentioned in the docs more clearly.

What is happening is that the lock is taken "by the outer call" and released in m's continuation. Since you call m twice it is released twice which leads to "operation not permitted".

This doesn't seem to be a 0.9.0 regression, this was already the case in 0.8.0 (and I suspect for ever). Not sure if anything can (or should) be done about this.

[mjambon]

Interesting use of the API :–)

I know, right 😄

I don't think it was ever meant to be used that way, one API call represent one logging operation and a single call to m.

It makes sense. It was a case where I wanted to print a list of things on one line and another list on another line.

It would be good to ensure that m is called exactly once but I'm not sure how to do this. I guess m could check and set a bool ref and fail with an exception similarly to what's happening accidentally with the double call to unlock:

let m_was_called = ref false in
let m args =
  if !m_was_called then
    failwith "The log message formatter was called twice"
  else (
    m_was_called := true;
    ...
  )
in
(* run (fun m -> m ...) *)
...
(* check that m was called *)
if not !m_was_called then
  failwith "The log message formatter was not called"