crash with mod_log_rotate

Started by cousinhub, December 12, 2013, 06:56:35 AM

Previous topic - Next topic

cousinhub

Hello all,
Tested with Apache 2.4 and mod_log_rotate-1.0-2.4 (vc9 and vc11) .
Just for information, if you misspell the pattern of your log destination, httpd.exe just crash with "Error in module msvcr110.dll (+ some further BEX64 notices)" in application system events.
Just spent few hours to find out that in a couple of my numerous virtual hosts, I had written
Customlog X:/myfolder/mylogsfolder/mylog-acess-Y%-m%-d%.log
instead of
Customlog X:/myfolder/mylogsfolder/mylog-acess-%Y-%m-%d.log

I tested and it crashed with even one % misplaced.

Gregg

Confirmed!

Crash Dump:
> libapr-1.dll!win32_strftime_extra(char * s=0x022c4108, unsigned int max=0x0000002d, const char * format=0x022c40d8, const tm * tm=0x0006fdc4)  Line 190 + 0x16 bytes C
libapr-1.dll!apr_strftime(char * s=0x022c4108, unsigned int * retsize=0x0006fe08, unsigned int max=0x0000004c, const char * format=0x022c40d8, apr_time_exp_t * xt=0x0006fe28)  Line 217 + 0x20 bytes C
mod_log_rotate.so!_ap_server_root_relative@8()  - 0x97f bytes C
mod_log_rotate.so!_ap_server_root_relative@8()  - 0x862 bytes C
mod_log_rotate.so!_ap_server_root_relative@8()  - 0x298 bytes C
mod_log_config.so!open_config_log(server_rec * s=0x01858d98, apr_pool_t * p=0x00000000, config_log_state * cls=0x00000000, apr_array_header_t * default_format=0x703a27fb)  Line 1337 + 0xd bytes C
mod_log_config.so!open_multi_logs(server_rec * s=0x01858d98, apr_pool_t * p=0x00000000)  Line 1376 + 0xf bytes C
mod_log_config.so!init_config_log(apr_pool_t * pc=0x018307e0, apr_pool_t * p=0x01856890, apr_pool_t * pt=0x0185a8a0, server_rec * s=0x01858d98)  Line 1454 C
libhttpd.dll!ap_run_open_logs(apr_pool_t * pconf=0x018307e0, apr_pool_t * plog=0x01856890, apr_pool_t * ptemp=0x0185a8a0, server_rec * s=0x01858d98)  Line 163 + 0x32 bytes C
httpd.exe!main(int argc=0x00000001, const char * const * argv=0x019311f0)  Line 690 + 0x1a bytes C
httpd.exe!__tmainCRTStartup()  Line 586 + 0x17 bytes C


Crashes on the call to strftime in timestr.c (APR) line 190 [win32_strftime_extra]


185     if (j >= max) {
186         *s = '\0';  /* Defensive programming, okay since output is undefined*/
187         return_value = 0;
188    } else {
189         new_format[j] = '\0';
190 >       return_value = strftime(s, max, new_format, tm);
191     }
192     free(new_format);
193     return return_value;
194 }


The resulting behavior (the crash) is documented at Microsoft, who's supposed to handle the problem before it gets to this point is the question. One side will say the module should make sure it's sending a properly formatted string although I believe there is argument for APR to trap the resulting error as well. Not sure which route to take at this time.

I'd be interested to know how rotatelogs.exe handles this (since I assume it uses the function), there may be a clue in it or it may just crash as well.

I think Mario has had dealings with the module's author before, maybe he can bring it up to the author.

Thanks for the report.




mario

Quote from: Gregg on December 12, 2013, 08:05:38 AM

I think Mario has had dealings with the module's author before, maybe he can bring it up to the author.

Yes, but no. Mean I had contact but he never replied any of my mails and even in the mailing list he ignored my mails. So I had some changes, but only for myself. It never went into the code. Also the module is not offical ASF.

Well on git hub I shall add that note why it might crash with wrong formated syntax.

I think the module should check for the correct syntax, prevent a starting and put an error in the error log.

cousinhub

QuoteI'd be interested to know how rotatelogs.exe handles this (since I assume it uses the function), there may be a clue in it or it may just crash as well.
Just for info again, rotatelogs.exe was causing numerous (thousands) errors like those
AH00106: piped log program 'C:/Apache24/bin/rotatelogs.exe D:/lxxxx/xxxx-%Y-%m-%d.log 86400' failed unexpectedly
AH00106: piped log program 'C:/Apache24/bin/rotatelogs.exe D:/yyyy/yyyy-access-%Y-%m-%d.log 86400' failed unexpectedly
AH00106: piped log program 'C:/Apache24/bin/rotatelogs.exe D:/zzzz/zzzzz-access-%Y-%m-%d.log 86400' failed unexpectedly
AH00106: piped log program 'C:/Apache24/bin/rotatelogs.exe D:/wwww/wwwww-access-%Y-%m-%d.log 86400' failed unexpectedly
AH00106: piped log program 'C:/Apache24/bin/rotatelogs.exe D:/ttttt/ttttttt-access-%Y-%m-%d.log 86400' failed unexpectedly

There was no misspelling in the config files (at least not that I was aware of and none in all the log files)  but the server was getting these errors  after running 1 to 3 h and then quickly getting really unstable.
The same problem occurred with cronolog.exe so I think we are talking about a totally different problem.

I was never able to find out why and that's why I decided to switch to mod_log_rotate.

It was a transfer from an 5 years old server with Apache 2.2 vc6 (from the apache group) installed to a powerful brand new server. Just been able to run without rotating logs so far but the server is in production and has now been stable for the last 12 hours with rotating logs.
I might be able to sleep tonight. I'll check tomorrow morning, error log and all...
No news here will mean good news.

Thanks to everybody at apachehaus.com for compiling and delivering theses binaries.