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?