Lucee Windows Server 2019 IIS causing sporadic exceptions event ID 1309 on Boncode and Tomcat

Version Lucee 5.3.8.179-RC
Servlet Container Apache Tomcat/9.0.35
Java 11.0.11 (AdoptOpenJDK) 64bit
Host Name 127.0.0.1
OS Windows Server 2019 (10.0) 64bit
Architecture 64bit

I’m experiencing a strange issue on a default Windows 2019 Server installation. Sporadically, but several times a day, I get an timeout exception on certaint unpredictable requests, which are later viewable in Microsoft Event Viewer with the source

ASP.NET 4.0.30319.0
EVENT-ID: 1309

One example output is:

<System>
  <Provider Name="ASP.NET 4.0.30319.0" /> 
  <EventID Qualifiers="32768">1309</EventID> 
  <Level>3</Level> 
  <Task>3</Task> 
  <Keywords>0x80000000000000</Keywords> 
  <TimeCreated SystemTime="2021-06-21T11:56:43.607510900Z" /> 
  <EventRecordID>328388</EventRecordID> 
  <Channel>Application</Channel> 
  <Computer>somedomain.tld</Computer> 
  <Security /> 
 </System>


Event code: 3001 
Event message: Die Anforderung wurde abgebrochen. 
Event time: 21.06.2021 13:56:43 
Event time (UTC): 21.06.2021 11:56:43 
Event ID: 5b9466197ae54e0d8145993c7b72d3cc 
Event sequence: 6 
Event occurrence: 4 
Event detail code: 0 
 
Application information: 
    Application domain: /LM/W3SVC/2/ROOT-1-132687146831469662 
    Trust level: Full 
    Application Virtual Path: / 
    Application Path: E:\wwwroot_net\ 
    Machine name: TPX 
 
Process information: 
    Process ID: 5340 
    Process name: w3wp.exe 
    Account name: IIS APPPOOL\global 
 
Exception information: 
    Exception type: HttpException 
    Exception message: Zeit für Anforderung überschritten.


Request information: 
    Request URL: https://somedomain.tld/some-path-1/some-path-2
    Request path: /some-path-1/some-path-2 
    User host address: 89.x.x.x 
    User:  
    Is authenticated: False 
    Authentication Type:  
    Thread account name: IIS APPPOOL\global 
 
Thread information: 
    Thread ID: 117 
    Thread account name: IIS APPPOOL\global 
    Is impersonating: False 
    Stack trace: 
 
 
Custom event details: 

As soon as this issue occurs for that request, the issue persists for every consecuting request of that same path/link.

There are no Stack Trace or Custom event details printed. This kind of Event-IDs are usually caused by timeout on Tomcat. I first thought it could be Lucee timing out, but if I directly try it through port 8888 the page is displayed instantly, while on IIS port 443 the issue persists (BUT ONLY FOR THAT LINK). So my first thought was an Boncode AJP issue.

So I’ve started logging Boncode on loglevel 1 and I was getting this type of error for the links throwing that event-id:

Boncode Error:

- 1.0.41 ERROR 
Stream reading problem (2)(5), we stopped waiting on Tomcat response. You may have shutdown Tomcat unexpectedly
Der Thread wurde abgebrochen.
   bei BonCodeAJP13.BonCodeAJP13ServerConnection.ReadStream(Byte[]& receivedPacketBuffer, String readOrigin)
   bei BonCodeAJP13.BonCodeAJP13ServerConnection.ComunicateWithTomcat()
- 1.0.41 ERROR 
TCP Client level -- Server/Port:localhost/8009
Der Thread wurde abgebrochen.
   bei BonCodeAJP13.BonCodeAJP13ServerConnection.ComunicateWithTomcat()
   bei BonCodeAJP13.BonCodeAJP13ServerConnection.HandleConnection()
   bei BonCodeAJP13.BonCodeAJP13ServerConnection.p_CreateConnection(BonCodeAJP13PacketCollection packetsToSend)

What is strange is, I’m NOT getting that typical Boncode General Communication error and Tomcat is still fully available, because everything else seems fine and looks to be working ok: If I open the same page through port 8888, everything is instantly displayed. But opening on IIS the error keeps displaying.

So my first thing was trying a greater packetsize as described in Boncodes documentation and with the AJP Connector setting in server.xml:

<Connector protocol="AJP/1.3"
	    port="8009"
	    secretRequired="false"
	    redirectPort="8443" 
	    address="::1"
	    packetSize="16384"/>

but that also didn’t work. Also, Lucee and Tomcat don’t throw any exception at all.

Further, as soon as I restart Tomcat the links causing the issue work again normally. But after some time, another link will popup in Windows Event Viewer with the same issue.

I don’t know what to try further, thus I’m asking here if others might be experiencing the same issue and know what would be the next step to try out? @Bilal, maybe you can tell what would you try next?

This sounds like a thread was terminated or crashed in the IIS connection pool.

Could you supply your boncode configuration file (remove any secrects).

Hi Bilal, thanks for replying… I have more information, but here is the setting first:

<Settings>
<Server>localhost</Server>
<Port>8009</Port>
<EnableRemoteAdmin>false</EnableRemoteAdmin>
<EnableHeaderDataSupport>False</EnableHeaderDataSupport>
<ForceSecureSession>False</ForceSecureSession>
<AllowEmptyHeaders>False</AllowEmptyHeaders>
<PacketSize>16384</PacketSize>
<LogLevel>1</LogLevel>
<LogDir>H:\logging\boncode</LogDir>
</Settings>

mod_cfml and secrets are not set, thus here is my server.xml at the moment. I’ve added a second connector to catalina in server.xml just like @carehart described here, thinking it could have something to with the ::1 vs 127.0.0.1 address in the connectors, but that didn’t had any positive result neither. My connectors look like this now:

	<Connector protocol="AJP/1.3"
	    port="8009"
	    secretRequired="false"
	    redirectPort="8443" address="::1"
		packetSize="16384"
		maxConnections="-1"
		/>

	<Connector protocol="AJP/1.3"
	    port="8009"
	    secretRequired="false"
	    redirectPort="8443" address="127.0.0.1"
		packetSize="16384"
		maxConnections="-1"
		/>

What I can also tell is that I’ve enabled access logging in Tomcat and these requests are not being logged at all by Tomcats AccessLogValve.

Then I’ve enabled logging as posted by you in the boncode docs to add logging to MS Event viewer with the followin PS command:

New-EventLog –LogName Application –Source "BonCodeConnector"

Having now the following events additionally created:

- <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
- <System>
  <Provider Name="BonCodeConnector" /> 
  <EventID Qualifiers="0">417</EventID> 
  <Level>2</Level> 
  <Task>0</Task> 
  <Keywords>0x80000000000000</Keywords> 
  <TimeCreated SystemTime="2021-06-21T20:23:24.040332800Z" /> 
  <EventRecordID>328545</EventRecordID> 
  <Channel>Application</Channel> 
  <Computer>some-domainname.tld</Computer> 
  <Security /> 
  </System>
- <EventData>
  <Data>ProcessRequest: Der Thread wurde abgebrochen. bei BonCodeIIS.BonCodeCallHandler.ProcessRequest(HttpContext context)</Data> 
  </EventData>
  </Event>

and

  - <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
- <System>
  <Provider Name="BonCodeConnector" /> 
  <EventID Qualifiers="0">417</EventID> 
  <Level>2</Level> 
  <Task>0</Task> 
  <Keywords>0x80000000000000</Keywords> 
  <TimeCreated SystemTime="2021-06-21T20:23:24.037340800Z" /> 
  <EventRecordID>328544</EventRecordID> 
  <Channel>Application</Channel> 
 <Computer>some-domainname.tld</Computer> 
  <Security /> 
  </System>
- <EventData>
  <Data>Connection error 2: Connection between Tomcat and IIS experienced error. If you restarted Tomcat this is expected. (1) bei BonCodeAJP13.BonCodeAJP13ServerConnection.ConnectionError() bei BonCodeAJP13.BonCodeAJP13ServerConnection.p_CreateConnection(BonCodeAJP13PacketCollection packetsToSend) bei BonCodeIIS.BonCodeCallHandler.ProcessRequest(HttpContext context)</Data> 
  </EventData>
  </Event>

Again Bilal, thanks for looking into this.

We saw a very similar issue which we solved when we discovered the Connector declaration in server.xml had incorrect capitalisation and wasn’t perfectly right. We specify “maxThreads” rather than “maxConnections”, which corresponds to the MaxConnections in BonCodeAJP13.settings. Try adding this to your BonCode settings:
<MaxConnections>1000</MaxConnections>
and change your maxConnections line in server.xml to:
maxThreads="1000"

Thanks for the additional info.
A Connection error 2 is a very basic low level TCP/IP issue. We are asking the TCP/IP service to establish or reusable connection on AJP port to Tomcat.
When this fails, we automatically go through a clean up process (kill the active connection and reset the active IIS thread). This is the error you would see in Windows Event logs.

The question is rather why we cannot connect on AJP port to Tomcat.
This could be a timeout issue, or you are running out of available AJP connections.

Since you have a maxConnections specified I am not sure that connection is the issue. You can try to do an AJP connection to Tomcat when you experience this using a Telnet client to test.

On the timeout side, I would suggest that you look at setting proper idle timeouts on the connections that you have, There are some suggestions in the docs how to do this: For server.xml
connectionTimeout="121000" keepAliveTimeout="-1"

Also set the corresponding IIS time out in min in your Application Pool to 2m.

Let me know how it goes.

  • Bilal

Hello Bilal, thanks for your kind reply.

I’ve added the maxConnections to server.xml after the issue poping up only to see if it might have something to do with limited connectors. Because, as you’ve said, it looked to me like we’ve been “running out of available AJP connections”, I’ve added the “maxConnections” directive with the value “-1” to disable it (like specified in Tomcats documentation). If it happens again, I’ll try a telnet connection to port 8009 as you’ve said.

Now I’ve added the connectionTimeout="121000" keepAliveTimeout="-1" directives to the connector as follows:

	<Connector protocol="AJP/1.3"
	    port="8009"
	    secretRequired="false"
	    redirectPort="8443" address="::1"
		packetSize="16384"
		maxConnections="-1"
		connectionTimeout="121000" 
		keepAliveTimeout="-1"
		/>

I’ve now changed the “Idle Timeout (in minutes)” from 20(!!!) to 2 Minutes as shown in the image below:

At the moment the Boncode settings specified in C:\Windows\BonCodeAJP13.settings are unchanged like so:

<Settings>
<Server>localhost</Server>
<Port>8009</Port>
<EnableRemoteAdmin>false</EnableRemoteAdmin>
<EnableHeaderDataSupport>False</EnableHeaderDataSupport>
<ForceSecureSession>False</ForceSecureSession>
<AllowEmptyHeaders>False</AllowEmptyHeaders>
<PacketSize>16384</PacketSize>
<LogLevel>1</LogLevel>
<LogDir>H:\logging\boncode</LogDir>
</Settings>

I just restarted IIS and Tomcat, let’s see how it works! I’ll post the results here later to tell how it’s going. Again @Bilal , thanks you for your kind help and chiming in.

@Simon_Goldschmidt: Thank you very much for your kind reply Simon. I was about to try that out, but Bilal just answered and now I’m going to try his proposals first (since he is the creator of boncode AJP connector and has great expertise with this issues) . I don’t want to mix things up for now.

Just to close this thread, thanks to @Bilal this issue seems to be resolved now. My settings posted above may serve as documentation to others running into the same issue. Big thanks also to @Simon_Goldschmidt for trying to help!

@bilal, unfortunately the issue just reappeared. Same issue :frowning:, additional information: if I telnet port 8009 I get a normal connection. Do you know something I could try next?

Andreas:
If you have a non-zero <MaxConnections> value in BonCode Settings
you can try to set
0

This will will build all connections without a connection pool.

in Windows:
Regedit
HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\Tcpip\Parameters
Create Dword , MaxUserPort
Set to decimal value 65534

Create Dword, TcpTimedWaitDelay
Set to match your application time out, default is STUPIDLY long,
Set to decimal value 30

IN HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\Tcpip\Parameters
Enable Net DNA
EnableTCPA=1

HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\Tcpip\Parameters
Set your Default TTL, you can set as low as 32, high as 128
DefaultTTL=64 (decimal value)

HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\Tcpip\Parameters
TCPMaxDataRetransmissions=7 (decimal value)

now either restart your computer or restart the explorer.exe and network services, iis

Additionally, not sure how you have your Windows Server configured, but

If its running a DB on the same host, create a microsoft virtual adapter, bind it to a local non routable Ip address, then bind your sql server and configuration for DSN to it.

Additionally, add a by ip address the name of your “Internal server” bound to the port in WinRoot/system32/etc/drivers/hosts

That way your server is not spending Pointless systemcalls trying to find and then figure out its the host of its own services.

If your DB is located elsewhere, or is under heavy load, I would suggest putting a dedicated nic on its own VLAN or subnet, or need be directly connect it to the db server using a cross over cable.

Andreas
If you can always recreate it with one specific call it is not a timeout or connectionthread.
Something inside the call is causing a protocol failure.
A few things to check

  • what is the size of your cookies?
  • e.g. are you storing session in cookies?
  • are you certain you are changing the right config files for Boncode and Tomcat? E.g. You can call connector command for version on BonCode side.set Set a different port on Tomcat for AJP etc.

Feel free to touch base via email if yoiu have the URL and you wamt to share for me to look.

If you are using large cookies pleaae increase max packet size on both sides…

HTH,
Bilal

Hi Bilal,

sorry for answering late, but I 've decided to wait a little with the hope to catch/gather more details. The issue is still persisting, however, these requests are not many. I can find them in the windows event viewer whenever they get triggered. When I open them, the time out keeps coming but only until I restart IIS and Tomcat. After that everything is alright, however, at some time some other random link will have the same issue.

But(!!!) as I mentioned before, they only keep timing out for those requests going through IIS. I can directly open the same URL through Tomcat on 8888 and the page is shown instantly.

Now to your questions:

This is a legacy app with a pure application.cfm that uses default lucees cfml cookies cftoken/cfid for session handling. We don’t use other cookies. I think somewhere one or the other cookies might be generated as a cookie tester or somehting similar, but nothing really fancy or complicated.

Yes, I am. I’m pretty sure because it happened to me once in the past and I’ll never forget that again :smiley: (see my post here here.

Please find here the actual configuration with called from the localhost with the querystring ?BonCodeConfigList=true

BonCode Active Configuration: 
-----------------------------------------------
BONCODEAJP13_ADOBE_SUPPORT = False
BONCODEAJP13_PORT = 8009
BONCODEAJP13_SERVER = localhost
BONCODEAJP13_AUTOFLUSHDETECTION_TICKS = 0
BONCODEAJP13_AUTOFLUSHDETECTION_BYTES = 0
MAX_BONCODEAJP13_CONCURRENT_CONNECTIONS = 0
BONCODEAJP13_LOG_LEVEL = 1
BONCODEAJP13_LOG_DIR = H:\logging\boncode
BONCODEAJP13_LOG_FILE = BonCodeAJP13Connection
BONCODEAJP13_ENABLE_REMOTE_MANAGER = False
BONCODEAJP13_AUTOCOMPRESS = False
BONCODEAJP13_TEXT_MARK = System.String[]
BONCODEAJP13_MANAGER_URLS = System.String[]
BONCODEAJP13_MANAGER_FLEXURLS = System.String[]
BONCODEAJP13_HEADER_SUPPORT = False
BonCodeAjp13_DocRoot = E:\wwwroot\
BonCodeAjp13_PhysicalFilePath = E:\wwwroot\index.html
BONCODEAJP13_BLACKLIST_HEADERS = URL,SERVER_SOFTWARE,SERVER_NAME,SERVER_PROTOCOL
BONCODEAJP13_WHITELIST_HEADERS = 
BONCODEAJP13_FLUSH_TIMEOUT = 30
BONCODEAJP13_SERVER_READ_TIMEOUT = 120000
BONCODEAJP13_SERVER_WRITE_TIMEOUT = 0
BONCODEAJP13_FORCE_SECURE_SESSION = False
BONCODEAJP13_REMOTEADDR_FROM = 
BONCODEAJP13_ALLOW_EMTPY_HEADERS = False
BONCODEAJP13_PATHINFO_HEADER = xajp-path-info
BONCODEAJP13_ENABLE_HTTPSTATUSCODES = True
BONCODEAJP13_TOMCAT_DOWN_URL = 
BONCODEAJP13_TOMCAT_STREAM_ERRORMSG = 
BONCODEAJP13_TOMCAT_TCPCLIENT_ERRORMSG = 
BONCODEAJP13_PATH_PREFIX = 
MAX_BONCODEAJP13_PACKET_LENGTH = 16384
MAX_BONCODEAJP13_USERDATA_LENGTH = 16378
BONCODEAJP13_ENABLE_CLIENTFINGERPRINT = False
BONCODEAJP13_FINGERPRINTHEADERS = REMOTE_ADDR,HTTP_ACCEPT,HTTP_ACCEPT_CHARSET,HTTP_ACCEPT_ENCODING,HTTP_ACCEPT_LANGUAGE,HTTP_USER_AGENT,UA_CPU,REMOTE_HOST
BONCODEAJP13_SKIP_IISCUSTOMERRORS = False
BONCODEAJP13_LOG_IPFILTER = 
BONCODEAJP13_REQUEST_SECRET = 
BONCODEAJP13_FORCE_GC = False
BONCODE_MODCFML_SECRET = 
BONCODE_DOCROOT_OVERRIDE = 

Something that comes to my mind is that we have just made a large encoding migration (from ISO-8559-1/Windows1252 to UTF-8 everywhere. Can it be that a mismatch somewhere might trigger an error like this?

Should I simply send you the plane link of one of these URLs then?

@andreas, i’m just curious to know if you ever figured this out.

Good question. Not really. But what should I say… I let this issue open in my list for a while and couldn’t find any new event id 1309 with this same problem anymore. We still have a bunch of event id 1309, but these have all a good cause: they are caused by some bots (or somebody) trying to inject unallowed strings into the url (which is blocked by IIS causing event id 1309).

So, I never really figured out the root of the issue. But after a period of time these type of entries have stopped (or I couldn’t find any new ones). I suspect it has something to do with a windows update, but can’t really say to be sure. Hate when issues like these get resolved without knowing anything about it :confused:

If the event in eventviewer is 1309, its IIS trying to look for a ASP.net or other script that is timing out
Bots are one cause, slow performing applications are another, and the ever elusive semi stateful processing application that gets disconnected by a user moving networks.

While its best to pre-filter traffic before it hits your webhost, you can create a bot trap, you can use Apache HTTPD (its actually faster on Windows than Linux in some instances, go figure) or you can set your application time out to some absurd value (if you have a beefy box or just are annoyed by the error).

Note, this is mostly IIS looking for asp, as ideally your CFML is being proxied to the apphost.
You will want to edit executionTimeout, this is how long the script can run while connectionTimeout is how long the connection sits and chews up a virtual port connection before closing.

Your tweaking can vary greatly upon what you have going on with your application

1 Like

I was able to get rid of the issue by adding PacketSize 65536 and MaxConnections 1000 to BonCodeAJP13.settings. Neither worked alone but, together, they stopped the issue.

My thought on the values was that, since IIS already has both of those settings, it would pre-filter requests based on the IIS settings and send everything else to the AJP connector. Since the AJP connector settings are higher than IIS, it should handle anything IIS sends over… right?

In any event, it did seem to solve the issue (for now at least). Hopefully we won’t have to live with Windows/IIS/Boncode for much longer.

Just incase someone else comes along, this setup was

  • Windows Server 2019
  • IIS
  • CommandBox 5.4.1+00443 (Don’t tell Brad before we get it upgraded :wink:)
  • Lucee 5.3.8+201
  • Boncode AJP13 Connector 1.0.42 (latest)

This was also very useful. Thanks for pointing it out, @andreas
New-EventLog –LogName Application –Source "BonCodeConnector"

Setting MaxConnections to 1000 led to a new error being logged (though the app seemed to function fine).

The error was:
[ERROR] io.undertow.request: UT005011: Ignoring AJP request with prefix 18

Updating MaxConnections to 0 stopped that

There is a reason undertow is vastly unused, even at Redhat who bought and developed the technology where as Tomcat is used for everything critical and in production.

My suggestion, and this is not a slight at commandbox, or the work brad does on it, use commandbox to develop not for production servers.

install lucee on tomcat and you will sleep better, have less headaches and join the ranks of every major university, fortune 1000, western allied government, most western allied towns, in running one of the most stable, secure platforms on the planet.

Or you can keep your tech heresy (Undertow) and all the weird bugs, performance issues and stability problems it has to offer.

First of all thanks @bhartsfield and @Terry_Whitney for answering here and giving some points into a direction.

@bhartsfield I’ve just adapted the packetsize accordingly in boncode and tomcat. But it’s been a long time I didn’t see anything similar to the issue I had at first.

I’d also like to switch to Linux on this box and apache2. Maybe I’d do it somewhere in the future when 2019 comes out of lifecycle.

@Terry_Whitney The 1309s I typically see come from IIS request filters: Lots of malicious attacks through query strings… sqlinjections, directory traversal requests, etc, but also some strange broken links with illegal signs in the URL.

Again, thanks for posting!