Log4erl has problem with UTC timzone

[xue yong zhi]

I recently ran into an issue with log4erl on a system configured with
UTC timezone.

Whenever I try to login anything, it throws badmatch. And the problem
went away when I reconfigured the timezone to EDT.

$ erl
Erlang (BEAM) emulator version 5.5.5 [source] [async-threads:0]
[kernel-poll:false]

Eshell V5.5.5 (abort with ^G)
1> ok = application:start(log4erl),
1> ok = log4erl:conf("log4erl.conf"),
1> log4erl:info("server started~n").
ok
=ERROR REPORT==== 12-May-2009::04:25:47 ===
** gen_event handler {file_appender,file} crashed.
** Was installed in default_logger
** Last event was: {log,{log,info,
"server started~n",
[],
{{2009,5,12},{4,25,47}},
875250}}
** When handler state == {file_appender,
".",
"server",
{file_descriptor,prim_file,{#Port<0.105>,
7}},
0,
{log_type,size,100000,undefined},
5,
"log",
info,
[91,level,93,32,iso_format,
32,log,new_line]}
** Reason == {{badmatch,[{{2009,5,12},{4,25,47}},{{2009,5,12},
{4,25,47}}]},
[{log_formatter,get_token_value,2},
{lists,map,2},
{lists,map,2},
{file_appender,do_log,2},
{file_appender,handle_event,2},
{gen_event,server_update,4},
{gen_event,server_notify,4},
{gen_event,server_notify,4}]}


=ERROR REPORT==== 12-May-2009::04:25:47 ===
** Generic server <0.40.0> terminating
** Last message in was {gen_event_EXIT,
{file_appender,file},
{'EXIT',
{{badmatch,
[{{2009,5,12},{4,25,47}},
{{2009,5,12},{4,25,47}}]},
[{log_formatter,get_token_value,2},
{lists,map,2},
{lists,map,2},
{file_appender,do_log,2},
{file_appender,handle_event,2},
{gen_event,server_update,4},
{gen_event,server_notify,4},
{gen_event,server_notify,4}]}}}
** When Server state == [{appender,file_appender,file}]
** Reason for termination ==
** {appender_died,{'EXIT',{{badmatch,[{{2009,5,12},{4,25,47}},
{{2009,5,12},{4,25,47}}]},
[{log_formatter,get_token_value,2},
{lists,map,2},
{lists,map,2},
{file_appender,do_log,2},
{file_appender,handle_event,2},
{gen_event,server_update,4},
{gen_event,server_notify,4},
{gen_event,server_notify,4}]}}}

[Ahmed Ali]

Hi,

Can you please send me the content of the following:

- log4erl.conf (I only need the format you're using)
- /etc/localtime (if you're running in linux)
- date +%z

From erl shell, please send the following:
> calendar:local_time().
> erlang:now().

It seems that date is inserted twice in messages from log_manager.
Also, what is the version of log4erl you're using?

Regards,

Ahmed

[xue yong zhi]

On May 12, 3:23 am, Ahmed Ali <ahmed.naw...@gmail.com> wrote:
> Hi,
>
> Can you please send me the content of the following:
>
> - log4erl.conf (I only need the format you're using)

logger {
file_appender file{
dir = ".",
level = info,
file = "server",
type = size,
max = 100000,
suffix = log,
rotation = 5,
format = '[%L] %I %l%n'
}

%% Consloe appender with level set to warn
console_appender cmd{
level = warn,
format = '[%L] %I %l%n'

}
}

> - /etc/localtime (if you're running in linux)

# cat /etc/localtime
TZif2 UTCTZif2 UTC
UTC0


> - date +%z

# date +%z
+0000

> From erl shell, please send the following:
>
> > calendar:local_time().
> > erlang:now().
>

1> calendar:local_time().
{{2009,5,12},{17,40,35}}
2> erlang:now().
{1242,150040,808249}


In case youn are using amazon EC2, you can reproduce the bug easily by
launching ami-ef48af86, then run the following commands via SSH:
#apt-get update; apt-get upgrade; apt-get install erlang;
#wget http://log4erl.googlecode.com/files/log4erl-0.8.6.tar.gz;
#tar xzvf log4erl-0.8.6.tar.gz
#cd log4erl-0.8.6
#erl -noshell -s yecc file src/log4erl_parser.yrl -s init stop
#make
#cd ebin
#vi log4erl.conf
#erl

Erlang (BEAM) emulator version 5.5.5 [source] [async-threads:0]
[kernel-poll:false]

Eshell V5.5.5 (abort with ^G)
1> ok = application:start(log4erl),
1> ok = log4erl:conf("log4erl.conf"),
1> log4erl:info("server started~n").
ok

=ERROR REPORT==== 12-May-2009::17:37:32 ===

** gen_event handler {file_appender,file} crashed.
** Was installed in default_logger
** Last event was: {log,{log,info,
"server started~n",
[],

{{2009,5,12},{17,37,32}},
105399}}

** When handler state == {file_appender,
".",
"server",
{file_descriptor,prim_file,{#Port<0.105>,
7}},
0,
{log_type,size,100000,undefined},
5,
"log",
info,
[91,level,93,32,iso_format,
32,log,new_line]}

** Reason == {{badmatch,[{{2009,5,12},{17,37,32}},{{2009,5,12},
{17,37,32}}]},

[{log_formatter,get_token_value,2},
{lists,map,2},
{lists,map,2},
{file_appender,do_log,2},
{file_appender,handle_event,2},
{gen_event,server_update,4},
{gen_event,server_notify,4},
{gen_event,server_notify,4}]}

=ERROR REPORT==== 12-May-2009::17:37:32 ===

** Generic server <0.40.0> terminating
** Last message in was {gen_event_EXIT,
{file_appender,file},
{'EXIT',
{{badmatch,

[{{2009,5,12},{17,37,32}},
{{2009,5,12},{17,37,32}}]},

[{log_formatter,get_token_value,2},
{lists,map,2},
{lists,map,2},
{file_appender,do_log,2},
{file_appender,handle_event,2},
{gen_event,server_update,4},
{gen_event,server_notify,4},
{gen_event,server_notify,4}]}}}
** When Server state == [{appender,file_appender,file}]
** Reason for termination ==

** {appender_died,{'EXIT',{{badmatch,[{{2009,5,12},{17,37,32}},
{{2009,5,12},{17,37,32}}]},

[Ahmed Ali]

Hi,

I cannot see anything wrong with the code. I've done exactly as you
did and didn't have a problem. However, please do the following in
order to see what is going on with your case.

1- In file $LOG4ERL_DIR/include/log4erl.hrl, change line 15 in order
to remove the comment. Line 15 should be like the following:

-define(DEBUG, true).

2- Recompile log4erl

3 - Use the following log4erl.conf instead o the one you supplied:
logger {
dummy_appender dummy{
format = "a"

}

file_appender file{
dir = ".",
level = info,
file = "server",
type = size,
max = 100000,
suffix = log,
rotation = 5,
format = '[%L] %I %l%n'
}

%% Consloe appender with level set to warn
console_appender cmd{
level = warn,
format = '[%L] %I %l%n'
}
}

4- run the same steps below again and then send me the output.

Regards,

Ahmed

[Xue Yong Zhi]

Here is the output:

root@domU-12-31-38-00-94-66:~/log4erl-0.8.6/ebin# erl

Erlang (BEAM) emulator version 5.5.5 [source] [async-threads:0] [kernel-poll:false]

Eshell V5.5.5 (abort with ^G)
1> ok = application:start(log4erl),
1> ok = log4erl:conf("log4erl.conf"),
1> log4erl:info("server started~n").

log4erl: Starting log4erl app
log4erl_sup: Starting supervisor
log4erl: Starting process log4erllog4erl: starting log4erl server with default_logger default_logger
log4erl_sup: Adding {"default_logger",
  {log_manager,start_link,["default_logger"]},
  permanent,
  10000,
  worker,
  [log_manager]} to log4erl_sup
log_manager: log_manager adding Logger "default_logger"
log4erl_sup: Result in supervisor is {ok,<0.37.0>}
log_manager: add_appender dummy_appender with name dummy to default_logger with Conf {conf,
  [{format,
  "a"}]} 
log4erl_sup: Adding {dummy,
  {logger_guard,
  start_link,
  [default_logger,
  dummy_appender,
  dummy,
  {conf,[{format,"a"}]}]},
  permanent,
  10000,
  worker,
  [logger_guard]} to log4erl_sup
logger_guard: Starting guard 
logger_guard: add_sup()
logger_guard: Adding handler dummy_appender with name dummy for default_logger From {<0.37.0>,
  #Ref<0.0.0.59>}
Initializing dummy_appender with args = {conf,[{format,"a"}]}
log_manager: add_appender file_appender with name file to default_logger with Conf {conf,
  [{dir,
  "."},
  {level,
  info},
  {file,
  "server"},
  {type,
  size},
  {max,
  100000},
  {suffix,
  log},
  {rotation,
  5},
  {format,
  "[%L] %I %l%n"}]} 
log4erl_sup: Adding {file,
  {logger_guard,
  start_link,
  [default_logger,
  file_appender,
  file,
  {conf,
  [{dir,"."},
  {level,info},
  {file,"server"},
  {type,size},
  {max,100000},
  {suffix,log},
  {rotation,5},
  {format,"[%L] %I %l%n"}]}]},
  permanent,
  10000,
  worker,
  [logger_guard]} to log4erl_sup
logger_guard: Starting guard 
logger_guard: add_sup()
logger_guard: Adding handler file_appender with name file for default_logger From {<0.37.0>,
  #Ref<0.0.0.69>}
file_appender: file_appender:init() - 1 {".",
  "server",
  {size,100000},
  5,
  "log",
  info,
  "[%L] %I %l%n"}
file_appender: To parse format with customer format "[%L] %I %l%n"
log_formatter: log_formatter parsing "[%L] %I %l%n"
log_formatter: Received tokens [91,level,93,32,iso_format,32,log,new_line]
file_appender: Adding format of [91,level,93,32,iso_format,32,log,new_line]
file_appender: file_appender:init() with conf {file_appender,

  ".",
  "server",
  {file_descriptor,
  prim_file,

  {#Port<0.107>,7}},
  0,
  {log_type,
  size,
  100000,

  undefined},
  5,
  "log",
  info,
  [91,
  level,
  93,
  32,
  iso_format,
  32,
  log,
  new_line]}

log_manager: add_appender console_appender with name cmd to default_logger with Conf {conf,
  [{level,
  warn},
  {format,
  "[%L] %I %l%n"}]} 
log4erl_sup: Adding {cmd,
  {logger_guard,
  start_link,
  [default_logger,
  console_appender,
  cmd,
  {conf,[{level,warn},{format,"[%L] %I %l%n"}]}]},
  permanent,
  10000,
  worker,
  [logger_guard]} to log4erl_sup
logger_guard: Starting guard 
logger_guard: add_sup()
logger_guard: Adding handler console_appender with name cmd for default_logger From {<0.37.0>,
  #Ref<0.0.0.84>}
console_appender: Initializing console_appender with args = {warn,
  "[%L] %I %l%n"}
log_formatter: log_formatter parsing "[%L] %I %l%n"
log_formatter: Received tokens [91,level,93,32,iso_format,32,log,new_line]
console_appender: Tokens received is [91,
  level,
  93,
  32,
  iso_format,
  32,
  log,
  new_line]console_appender: State is {console_appender,
  warn,
  [91,level,93,32,iso_format,32,log,new_line]}log_manager: Logging:
 default_logger info "server started~n" []
console_appender: handl_event:log = {log,
  info,
  "server started~n",
  [],
  {{2009,5,13},{1,18,46}},
  160714}
file_appender: handl_event:log = {log,info,
  "server started~n",
  [],
  {{2009,5,13},{1,18,46}},
  160714}
file_appender: Formatting [91,level,93,32,iso_format,32,log,new_line]
log_formatter: log_formatter formatting log: {log,
  info,
  "server started~n",
  [],
  {{2009,5,13},{1,18,46}},
  160714}
dummy_appender received event {log,
  {log,
  info,
  "server started~n",
  [],
  {{2009,5,13},{1,18,46}},
  160714}}
logger_guard: logger_guard received exit message. Terminating now

=ERROR REPORT==== 13-May-2009::01:18:46 ===

** gen_event handler {file_appender,file} crashed.
** Was installed in default_logger
** Last event was: {log,{log,info,
  "server started~n",
  [],

  {{2009,5,13},{1,18,46}},
  160714}}

** When handler state == {file_appender,
  ".",
  "server",

  {file_descriptor,prim_file,{#Port<0.107>,7}},

  0,
  {log_type,size,100000,undefined},
  5,
  "log",
  info,
  [91,level,93,32,iso_format,32,log,new_line]}

** Reason == {{badmatch,[{{2009,5,13},{1,18,46}},{{2009,5,13},{1,18,46}}]},

  [{log_formatter,get_token_value,2},
  {lists,map,2},
  {lists,map,2},
  {file_appender,do_log,2},
  {file_appender,handle_event,2},
  {gen_event,server_update,4},
  {gen_event,server_notify,4},
  {gen_event,server_notify,4}]}

ok
=ERROR REPORT==== 13-May-2009::01:18:46 ===
** Generic server <0.41.0> terminating 

** Last message in was {gen_event_EXIT,
  {file_appender,file},
  {'EXIT',
  {{badmatch,

  [{{2009,5,13},{1,18,46}},
  {{2009,5,13},{1,18,46}}]},

  [{log_formatter,get_token_value,2},
  {lists,map,2},
  {lists,map,2},
  {file_appender,do_log,2},
  {file_appender,handle_event,2},
  {gen_event,server_update,4},
  {gen_event,server_notify,4},
  {gen_event,server_notify,4}]}}}
** When Server state == [{appender,file_appender,file}]
** Reason for termination == 

** {appender_died,{'EXIT',{{badmatch,[{{2009,5,13},{1,18,46}},
  {{2009,5,13},{1,18,46}}]},

  [{log_formatter,get_token_value,2},
  {lists,map,2},
  {lists,map,2},
  {file_appender,do_log,2},
  {file_appender,handle_event,2},
  {gen_event,server_update,4},
  {gen_event,server_notify,4},
  {gen_event,server_notify,4}]}}}

logger_guard: Starting guard 
2> logger_guard: add_sup()
logger_guard: Adding handler file_appender with name file for default_logger From {<0.37.0>,
  #Ref<0.0.0.108>}
file_appender: file_appender:init() - 1 {".",
  "server",
  {size,100000},
  5,
  "log",
  info,
  "[%L] %I %l%n"}
file_appender: To parse format with customer format "[%L] %I %l%n"
log_formatter: log_formatter parsing "[%L] %I %l%n"
log_formatter: Received tokens [91,level,93,32,iso_format,32,log,new_line]
file_appender: Adding format of [91,level,93,32,iso_format,32,log,new_line]
file_appender: file_appender:init() with conf {file_appender,

  ".",
  "server",
  {file_descriptor,
  prim_file,

  {#Port<0.111>,8}},
  0,
  {log_type,
  size,
  100000,

[Ahmed Ali]

Hi,

This problem has been fixed now. The issue is related to incorrect, I
think, output of calendar:local_time_to_universal_time_dst/1 which is
used with %I & %S specifiers in order to get universal time. For
difference, see below. It's strange to me that in R11, we get the same
time twice. I'll check with erlang mailing list to see what is the
reason for this. I made a change to log_formatter to handle this case
and will update source code in the web within next 2 days.

For the time being, please use %j and %T instead until this change is commited.

Thanks Xue Yong Zhi for the feedback.

Good luck

Ahmed

[Erlang R12]:
# erl
Eshell V5.6.4 (abort with ^G)
1> calendar:local_time_to_universal_time_dst({{2009,5,13},{17,57,50}}).
[{{2009,5,13},{13,57,50}}]

[Erlang R11]:

# erl
Erlang (BEAM) emulator version 5.5.5 [source] [async-threads:0]
[kernel-poll:false]

Eshell V5.5.5 (abort with ^G)

1> calendar:local_time_to_universal_time_dst({{2009,5,13},{17,57,50}}).
[{{2009,5,13},{17,57,50}},{{2009,5,13},{17,57,50}}]

On Wed, May 13, 2009 at 4:59 PM, Ahmed Ali <ahmed....@gmail.com> wrote:
> Hi,
>

> Let's meet in gmail chat to discuss this further. I'd like to do this
> in real time. I want to see exactly how timezone changes affect my
> code. I will be on gmail chat during the next 2 hours. If not today,
> then I'll be available tomorrow from around 10:00 GMT to 12:00 GMT.
>
> For the time being, please do the below in erlang shell and send me
> the output. Also, do you have an old log4erl release setting in erlang
> lib directory? To overcome this, you can run erl -pa $LOG4ERL_DIR.
> Also, can you please run "ls -ltr /etc/localtime" to see what is
> /etc/locatime linked to.
>
>> {ok, Tokens} = log_formatter:parse("[%L] %I %l%n").
>> S = log_formatter:format({log, info,"server started~n",[],{{2009,5,13},{1,18,46}},160714}, Tokens).
>> io:format(S).
>
> Best regards,
>
> Ahmed