ironbee/ironbee — Issue #15: Commit ee9db659495f4cf59ae3e778cc14b0f2dd986482 breaks error logging when non-existent module passed to LoadModule
Author: wmetcalf
Created: 2011-11-28 17:09:58+00:00
State: open

With the latest commit ee9db659495f4cf59ae3e778cc14b0f2dd986482 we no longer log an error when a non-existent module is loaded. If we revert back to commit 6173ed7b4c8021d35d50a0418406947f8df7d96b we see the expected behavior.

```
2011-11-28 10:55:47,022 - root - ERROR - failed to find match of (?sm)^.+\[error\]\sIronBee\:\s\[\d+\]\sERROR\s\-\sFailed\sto\sload\smodule\s\"Abel\.so\" in buffer [Mon Nov 28 10:55:44 2011] [info] mod_unique_id: using ip addr 127.0.1.1
[Mon Nov 28 10:55:45 2011] [info] mod_ironbee IronBee/0.3.0 (ABI 201110300) loading.
[Mon Nov 28 10:55:45 2011] [info] mod_unique_id: using ip addr 127.0.1.1
[Mon Nov 28 10:55:46 2011] [debug] mod_ironbee.c(868): IronBee: Parsing config: /home/coz/ironbee-qa/apache_httpd_server_root/conf/ironbee.conf
[Mon Nov 28 10:55:46 2011] [debug] mod_ironbee.c(173): IronBee: [18902] PCRE Status: compiled="7.8 2008-09-05" loaded="7.8 2008-09-05"
[Mon Nov 28 10:55:46 2011] [debug] mod_ironbee.c(173): IronBee: [18902] AC Status: compiled="0.1 20110812" Radix Matcher registered
[Mon Nov 28 10:55:46 2011] [debug] mod_ironbee.c(173): IronBee: [18902] AC Status: compiled="0.1 AC_DATE" BinRadix Matcher registered
[Mon Nov 28 10:55:46 2011] [debug] mod_ironbee.c(173): IronBee: [18902] AC Status: compiled="0.1 20110812" AC Matcher registered
[Mon Nov 28 10:55:46 2011] [debug] mod_ironbee.c(173): IronBee: [18902] LuaFFI - example.onModuleLoad ib=0x7f167cbaf9d0
[Mon Nov 28 10:55:46 2011] [emerg] IronBee: [18902] LuaFFI - TestLogLevel 0 debuglog.onModuleLoad ib=0x7f167cbaf9d0
[Mon Nov 28 10:55:46 2011] [alert] IronBee: [18902] LuaFFI - TestLogLevel 1 debuglog.onModuleLoad ib=0x7f167cbaf9d0
[Mon Nov 28 10:55:46 2011] [error] IronBee: [18902] LuaFFI - TestLogLevel 2 debuglog.onModuleLoad ib=0x7f167cbaf9d0
[Mon Nov 28 10:55:46 2011] [warn] IronBee: [18902] LuaFFI - TestLogLevel 3 debuglog.onModuleLoad ib=0x7f167cbaf9d0
[Mon Nov 28 10:55:46 2011] [debug] mod_ironbee.c(173): IronBee: [18902] LuaFFI - TestLogLevel 4 debuglog.onModuleLoad ib=0x7f167cbaf9d0
[Mon Nov 28 10:55:46 2011] [debug] mod_ironbee.c(173): IronBee: [18902] AUDITLOG PARTS: 0x000002ef
[Mon Nov 28 10:55:46 2011] [debug] mod_ironbee.c(173): IronBee: [18902] Creating list for phase=1
[Mon Nov 28 10:55:46 2011] [debug] mod_ironbee.c(173): IronBee: [18902] List for phase=1 list=0x7f167cbc7490
[Mon Nov 28 10:55:46 2011] [debug] mod_ironbee.c(173): IronBee: [18902] POCSIG: "request_line" "bar" "TESTING: Matched bar in request line." phase=1 ctx=0x7f167cbcab70
[Mon Nov 28 10:55:46 2011] [debug] mod_ironbee.c(173): IronBee: [18902] Creating list for phase=1
[Mon Nov 28 10:55:46 2011] [debug] mod_ironbee.c(173): IronBee: [18902] List for phase=1 list=0x7f167cbc7559
[Mon Nov 28 10:55:46 2011] [debug] mod_ironbee.c(173): IronBee: [18902] POCACSIG: "request_line" "(bar)+" "TESTING: Matched foo and (bar)+ in request line." phase=1 ctx=0x7f167cbcab70
[Mon Nov 28 10:55:46 2011] [debug] mod_ironbee.c(173): IronBee: [18902] pattern foo added to the AC tree 7cbc7650
[Mon Nov 28 10:55:46 2011] [debug] mod_ironbee.c(173): IronBee: [18902] AUDITLOG PARTS: 0x000006ef
[Mon Nov 28 10:55:46 2011] [debug] mod_ironbee.c(872): IronBee: Destroying config parser
[Mon Nov 28 10:55:46 2011] [notice] mod_ironbee IronBee/0.3.0 (ABI 201110300) configured.
[Mon Nov 28 10:55:46 2011] [debug] mod_ironbee.c(292): IronBee: Child init pid=18903
[Mon Nov 28 10:55:46 2011] [debug] proxy_util.c(1806): proxy: grabbed scoreboard slot 0 in child 18903 for worker proxy:reverse
[Mon Nov 28 10:55:46 2011] [debug] proxy_util.c(1922): proxy: initialized single connection worker 0 in child 18903 for (*)
[Mon Nov 28 10:55:46 2011] [debug] mod_ironbee.c(292): IronBee: Child init pid=18904
[Mon Nov 28 10:55:46 2011] [debug] proxy_util.c(1806): proxy: grabbed scoreboard slot 0 in child 18904 for worker proxy:reverse
[Mon Nov 28 10:55:46 2011] [debug] proxy_util.c(1825): proxy: worker proxy:reverse already initialized
[Mon Nov 28 10:55:46 2011] [debug] proxy_util.c(1922): proxy: initialized single connection worker 0 in child 18904 for (*)
[Mon Nov 28 10:55:46 2011] [debug] mod_ironbee.c(292): IronBee: Child init pid=18905
[Mon Nov 28 10:55:46 2011] [debug] proxy_util.c(1806): proxy: grabbed scoreboard slot 0 in child 18905 for worker proxy:reverse
[Mon Nov 28 10:55:46 2011] [debug] proxy_util.c(1825): proxy: worker proxy:reverse already initialized
[Mon Nov 28 10:55:46 2011] [debug] proxy_util.c(1922): proxy: initialized single connection worker 0 in child 18905 for (*)
[Mon Nov 28 10:55:46 2011] [notice] Apache/2.2.14 (Ubuntu) configured -- resuming normal operations
[Mon Nov 28 10:55:46 2011] [debug] mod_ironbee.c(292): IronBee: Child init pid=18906
[Mon Nov 28 10:55:46 2011] [info] Server built: Nov 3 2011 03:29:23
[Mon Nov 28 10:55:46 2011] [debug] prefork.c(1013): AcceptMutex: sysvsem (default: sysvsem)
[Mon Nov 28 10:55:46 2011] [debug] proxy_util.c(1806): proxy: grabbed scoreboard slot 0 in child 18906 for worker proxy:reverse
[Mon Nov 28 10:55:46 2011] [debug] proxy_util.c(1825): proxy: worker proxy:reverse already initialized
[Mon Nov 28 10:55:46 2011] [debug] proxy_util.c(1922): proxy: initialized single connection worker 0 in child 18906 for (*)
[Mon Nov 28 10:55:46 2011] [debug] mod_ironbee.c(292): IronBee: Child init pid=18907
[Mon Nov 28 10:55:46 2011] [debug] proxy_util.c(1806): proxy: grabbed scoreboard slot 0 in child 18907 for worker proxy:reverse
[Mon Nov 28 10:55:46 2011] [debug] proxy_util.c(1825): proxy: worker proxy:reverse already initialized
[Mon Nov 28 10:55:46 2011] [debug] proxy_util.c(1922): proxy: initialized single connection worker 0 in child 18907 for (*)
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(327): IronBee: ironbee_pre_connection remote=127.0.0.1:37868 local=127.0.0.1:9931
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventConnStarted ib=0x7f167cbaf9d0 conn=0x7f167cbdf480
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventConnOpened ib=0x7f167cbaf9d0 conn=0x7f167cbdf480
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventHandleContextConn ib=0x7f167cbaf9d0 conn=0x7f167cbdf480
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - Created PCRE matcher=0x7f167cbe97c8
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - Created radix matcher=0x7f167cbe97f5
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - Created ac matcher=0x7f167cbe9823
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventHandleConnect ib=0x7f167cbaf9d0 conn=0x7f167cbdf480
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(602): FETCH BRIGADE (buffering)
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventConnDataIn: GET / HTTP/1.1\r\nHost: foo\r\n\r\n
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventTxStarted ib=0x7f167cbaf9d0 tx=4ed3bd13-19e2-4f52-8fff-49d7bb6a8e3c
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventRequestStarted ib=0x7f167cbaf9d0 tx=4ed3bd13-19e2-4f52-8fff-49d7bb6a8e3c
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventTxDataIn[2]: GET / HTTP/1.1\r\n
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventTxDataIn[3]: Host: foo\r\n
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventTxDataIn[3]: \r\n
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] Adding request_headers fields
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventRequestHeaders ib=0x7f167cbaf9d0 tx=4ed3bd13-19e2-4f52-8fff-49d7bb6a8e3c
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventHandleContextTx ib=0x7f167cbaf9d0 tx=4ed3bd13-19e2-4f52-8fff-49d7bb6a8e3c
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] No signatures for phase=0 ctx=0x7f167cbcab70
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventHandleRequestHeaders ib=0x7f167cbaf9d0 tx=4ed3bd13-19e2-4f52-8fff-49d7bb6a8e3c
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - Request line is a field type: 4
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - Request Line cvalue: 0x7f167cbeedbd
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - REQUEST_LINE=GET / HTTP/1.1
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - Lower case request line is a field type: 4
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - Lower case Request Line value: get / http/1.1
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - Request Line value: GET / HTTP/1.1
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - Request Headers is a field type: 5
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - REQUEST_HEADERS.Host=foo
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - HTTP Host Header is a field type: 4
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - HTTP REQUEST_HEADERS.HOST=foo
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - Request cookies is a field type: 5
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - Request ARGS is a field type: 5
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - Request Line does not match: (?i:foo)
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] Executing 1 signatures for phase=1 ctx=0x7f167cbcab70
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] PocSig: Matching "bar" against field "request_line"
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] PocSig NOMATCH
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] Matching AGAINST AC tree 7cbc7650
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventRequestBody ib=0x7f167cbaf9d0 tx=4ed3bd13-19e2-4f52-8fff-49d7bb6a8e3c
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventHandleRequest ib=0x7f167cbaf9d0 tx=4ed3bd13-19e2-4f52-8fff-49d7bb6a8e3c
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] No signatures for phase=2 ctx=0x7f167cbcab70
[Mon Nov 28 10:55:47 2011] [error] [client 127.0.0.1] Attempt to serve directory: /home/coz/ironbee-qa/apache_httpd_server_root/htdocs/
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventConnDataOut: HTTP/1.1 404 Not Found\r\nDate: Mon, 28 Nov 2011 16:55:47 GMT\r\nServer: Apache/2.2.14 (Ubuntu)\r\nContent-Length: 198\r\nContent-Type: text/html; charset=iso-8859-1\r\n\r\n
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventResponseStarted ib=0x7f167cbaf9d0 tx=4ed3bd13-19e2-4f52-8fff-49d7bb6a8e3c
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventTxDataOut[type=2]: HTTP/1.1 404 Not Found
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventTxDataOut[type=3]: Date: Mon, 28 Nov 2011 16:55:47 GMT\r\n
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventTxDataOut[type=3]: Server: Apache/2.2.14 (Ubuntu)\r\n
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventTxDataOut[type=3]: Content-Length: 198\r\n
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventTxDataOut[type=3]: Content-Type: text/html; charset=iso-8859-1\r\n
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventTxDataOut[type=3]: \r\n
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventResponseHeaders ib=0x7f167cbaf9d0 tx=4ed3bd13-19e2-4f52-8fff-49d7bb6a8e3c
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventHandleResponseHeaders ib=0x7f167cbaf9d0 tx=4ed3bd13-19e2-4f52-8fff-49d7bb6a8e3c
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] No signatures for phase=3 ctx=0x7f167cbcab70
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventConnDataOut: \n

\n

404 Not Found

\n

\n

Not Found

\n

The requested URL / was not found on this server.

\n

\n
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventTxDataOut[type=4]: \n

\n

404 Not Found

\n

\n

Not Found

\n

The requested URL / was not found on this server.

\n

\n
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventResponseBody ib=0x7f167cbaf9d0 tx=4ed3bd13-19e2-4f52-8fff-49d7bb6a8e3c
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventHandleResponse ib=0x7f167cbaf9d0 tx=4ed3bd13-19e2-4f52-8fff-49d7bb6a8e3c
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] No signatures for phase=4 ctx=0x7f167cbcab70
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventResponseFinished ib=0x7f167cbaf9d0 tx=4ed3bd13-19e2-4f52-8fff-49d7bb6a8e3c
[Mon Nov 28 10:55:47 2011] [warn] IronBee: [18903] AUDITLOG INDEX: /home/coz/ironbee-qa/apache_httpd_server_root/logs/audit/auditlog.log
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] AUDITLOG: /home/coz/ironbee-qa/apache_httpd_server_root/logs/audit/20111128-1655/4ed3bd13-19e2-4f52-8fff-49d7bb6a8e3c.log
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] ERROR - No events in audit log
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventHandlePostprocess ib=0x7f167cbaf9d0 tx=4ed3bd13-19e2-4f52-8fff-49d7bb6a8e3c
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] No signatures for phase=5 ctx=0x7f167cbcab70
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventTxFinished ib=0x7f167cbaf9d0 tx=4ed3bd13-19e2-4f52-8fff-49d7bb6a8e3c
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(602): FETCH BRIGADE (buffering)
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(292): IronBee: Child init pid=18908
[Mon Nov 28 10:55:47 2011] [debug] proxy_util.c(1806): proxy: grabbed scoreboard slot 0 in child 18908 for worker proxy:reverse
[Mon Nov 28 10:55:47 2011] [debug] proxy_util.c(1825): proxy: worker proxy:reverse already initialized
[Mon Nov 28 10:55:47 2011] [debug] proxy_util.c(1922): proxy: initialized single connection worker 0 in child 18908 for (*)
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(602): FETCH BRIGADE (buffering)
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(633): IronBee: ironbee_in client closed connection (70014)
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventConnClosed ib=0x7f167cbaf9d0 conn=0x7f167cbdf480
[Mon Nov 28 10:55:47 2011] [debug] mod_ironbee.c(173): IronBee: [18903] LuaFFI - example.onEventHandleDisconnect ib=0x7f167cbaf9d0 conn=0x7f167cbdf480

2011-11-28 10:55:49,036 - root - ERROR - apache process with pid of 18902 no longer running

====================IronBee Test Results====================
test20:Test of LoadModule Nonexistent [ fail ]:failed to match (?sm)^.+\[error\]\sIronBee\:\s\[\d+\]\sERROR\s\-\sFailed\sto\sload\smodule\s\"Abel\.so\":re needed by test apache_httpd_server_root/logs/error.log in file test20
==========================Summary===========================
Pass 0
Fail 1

make distclean
git checkout -b 6173ed7b4c8021d35d50a0418406947f8df7d96b 6173ed7b4c8021d35d50a0418406947f8df7d96b
./autogen.sh
./configure --with-gcc-optimization-level=0 --with-ats-includes=/usr/local/trafficserver/include/ --enable-cli
make -j8
make check -j8
sudo make install

coz@coz-desktop:~/ironbee-qa (master)$ ./ironbee_test.py --console-log-level="error" --file-glob="tests/*.json" --file-format="ironbee_test_file" --ironbee-test-regex="test20"
WARNING: No route found for IPv6 destination :: (no default route?)
====================IronBee Test Results====================
test20:Test of LoadModule Nonexistent [ pass ]
==========================Summary===========================
Pass 1
Fail 0
```