Fix crash in performance logs when the dispatch rule doesn't match

To reproduce the crash just enable perf logs and try to open a page which doesn't match the dispatch rules (e.g. http://site:8000/manual). The crash happens because end_time and finish_time in wm_log_data are not being initialized.

I've added the initialization of end_time to webmachine_perf_logger which all functions have to call in order to log the performance log (thus I'm removing the initialization of end_time in webmachine_mochiweb:loop because it will be initialized in the logger function anyway).

As for initialization of finish_time the standard way is setting that field in the send_response/1 function. However, most functions in the dispatch loop were skipping that initialization because of some reason and were calling the send_response/2 function directly, which was leaving that field empty. I consider that as a mistake and so I made the send_response/2 private to not confuse people in the future.

Of course I checked that no other part of webzmachine sources use send_response/2, however there is one usage in Zotonic itself which I will send in another pull request.

Ah, and here is the crash itself (with some data obfuscated):

2013-07-26 13:42:44 =ERROR REPORT====
** Generic server webmachine_perf_logger terminating
** Last message in was {log,{wm_log_data,617739586,undefined,{1374,846164,614894},'GET',{7,{"host",{'Host',"*****:8000"},{"accept",{'Accept',"text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"},nil,{"accept-language",{'Accept-Language',"en-US,en;q=0.5"},{"accept-encoding",{'Accept-Encoding',"gzip, deflate"},nil,nil},{"cookie",{'Cookie',"z_pid=*****; z_ua=*****; z_sid=*****"},{"connection",{'Connection',"keep-alive"},nil,nil},nil}}},{"user-agent",{'User-Agent',"Mozilla/5.0 (Windows NT 6.1; WOW64; rv:21.0) Gecko/20100101 Firefox/21.0"},nil,nil}}},"*****","/manual",{1,1},404,507,undefined,undefined,{dict,3,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[],[[ua_class|desktop],[ua_props,{is_user_select,true},{has_pointer,true},{is_desktop,true},{is_crawler,false},{is_wireless_device,false},{is_tablet,false},{ajax_support_javascript,true},{device_os,<<"-">>},{displayWidth,1680},{displayHeight,1050},{inputDevices,<<"-">>},{parentId,<<"generic-">>},{model,<<"browser">>},{vendor,<<"desktop">>},{id,<<"desktopDevice">>}]],[[zotonic_host|*****]],[],[],[],[],[],[],[],[],[],[],[]}}}}}
** When Server state == {state,{2013,7,26,13},"/usr/home/*****/log/perf/perf.log",{webmachine_perf_logger,"/usr/home/*****/log/perf/perf.log.2013_07_26_13",{file_descriptor,prim_file,{#Port<0.20919>,36}}}}
** Reason for termination ==
** {function_clause,[{webmachine_util,now_diff_milliseconds,[undefined,{1374,846164,714354}],[{file,"src/webmachine_util.erl"},{line,323}]},{webmachine_perf_logger,format_req,1,[{file,"src/webmachine_perf_logger.erl"},{line,113}]},{webmachine_perf_logger,handle_call,3,[{file,"src/webmachine_perf_logger.erl"},{line,53}]},{gen_server,handle_msg,5,[{file,"gen_server.erl"},{line,588}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,227}]}]}
2013-07-26 13:42:44 =CRASH REPORT====
  crasher:
    initial call: webmachine_perf_logger:init/1
    pid: <0.424.0>
    registered_name: webmachine_perf_logger
    exception exit: {{function_clause,[{webmachine_util,now_diff_milliseconds,[undefined,{1374,846164,714354}],[{file,"src/webmachine_util.erl"},{line,323}]},{webmachine_perf_logger,format_req,1,[{file,"src/webmachine_perf_logger.erl"},{line,113}]},{webmachine_perf_logger,handle_call,3,[{file,"src/webmachine_perf_logger.erl"},{line,53}]},{gen_server,handle_msg,5,[{file,"gen_server.erl"},{line,588}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,227}]}]},[{gen_server,terminate,6,[{file,"gen_server.erl"},{line,747}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,227}]}]}
    ancestors: [webmachine_sup,<0.388.0>]
    messages: []
    links: [<0.389.0>,#Port<0.20919>]
    dictionary: []
    trap_exit: false
    status: running
    heap_size: 6765
    stack_size: 24
    reductions: 128092
  neighbours:
2013-07-26 13:42:44 =SUPERVISOR REPORT====
     Supervisor: {local,webmachine_sup}
     Context:    child_terminated
     Reason:     {function_clause,[{webmachine_util,now_diff_milliseconds,[undefined,{1374,846164,714354}],[{file,"src/webmachine_util.erl"},{line,323}]},{webmachine_perf_logger,format_req,1,[{file,"src/webmachine_perf_logger.erl"},{line,113}]},{webmachine_perf_logger,handle_call,3,[{file,"src/webmachine_perf_logger.erl"},{line,53}]},{gen_server,handle_msg,5,[{file,"gen_server.erl"},{line,588}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,227}]}]}
     Offender:   [{pid,<0.424.0>},{name,webmachine_perf_logger},{mfargs,{webmachine_perf_logger,start_link,["/usr/home/*****/log/perf"]}},{restart_type,permanent},{shutdown,5000},{child_type,worker}]

zotonic / webzmachine

Fix crash in performance logs when the dispatch rule doesn't match #12