Error Request for Progress Review – ipurch DB Abnormal Shutdown with WebSpeed Memory Violation and APW/AIW Lock Stack Errors

Mike

Mike

Moderator
We had a situation where db went down we found db logs below:- We need to find RCA why and which user did this? and how to avoid in future this?
[2026/07/13@06:19:46.015-0500] P-17611 T-140394007668160 I AIMGT 22: (3778) This is after-image file number 213817 since the last AIMAGE BEGIN
[2026/07/13@06:19:51.016-0500] P-17611 T-140394007668160 I AIMGT 22: (13199) After-image extent /ai/prod/ipurch/ipurchprod.a6 has been copied to /backup/prod/aiarch/ipurch/db~prod~ipurch~ipurchprod.20200606.062533.00213816.ipurchprod.a6.
[2026/07/13@06:19:51.017-0500] P-17611 T-140394007668160 I AIMGT 22: (3789) Marked after-image extent /ai/prod/ipurch/ipurchprod.a6 EMPTY.
[2026/07/13@11:32:32.000+0000] P-12422 T-140278625640704 I WSAGENT28: (49) SYSTEM ERROR: Memory violation.
[2026/07/13@11:32:32.000+0000] P-12422 T-140278625640704 I WSAGENT28: (439) ** Save file named core for analysis by Progress Software Corporation.
[2026/07/13@11:32:32.000+0000] P-12422 T-140278625640704 I WSAGENT28: (-----) Generating /apps/ipurchase/work/webspeed/agents/protrace.12422
[2026/07/13@06:33:13.315-0500] P-17605 T-139854071501248 I WDOG 21: (2527) Disconnecting dead user 28.
[2026/07/13@11:33:37.000+0000] P-11762 T-140200292004096 I WSAGENT27: (49) SYSTEM ERROR: Memory violation.
[2026/07/13@11:33:37.000+0000] P-11762 T-140200292004096 I WSAGENT27: (439) ** Save file named core for analysis by Progress Software Corporation.
[2026/07/13@11:33:37.000+0000] P-11762 T-140200292004096 I WSAGENT27: (-----) Generating /apps/ipurchase/work/webspeed/agents/protrace.11762
[2026/07/13@06:33:39.559-0500] P-17338 T-140657448198400 I WSAGENT26: (452) Login by mfg on batch.
[2026/07/13@06:33:39.559-0500] P-17339 T-140297703747840 I WSAGENT28: (452) Login by mfg on batch.
[2026/07/13@06:33:39.559-0500] P-17334 T-140710392152320 I WSAGENT29: (452) Login by mfg on batch.
[2026/07/13@06:33:39.560-0500] P-17326 T-140587959419136 I WSAGENT30: (452) Login by mfg on batch.
[2026/07/13@06:33:39.561-0500] P-17340 T-139962508124416 I WSAGENT31: (452) Login by mfg on batch.
[2026/07/13@06:33:39.562-0500] P-17338 T-140657448198400 I WSAGENT26: (7129) Usr 26 set name to mfg.
[2026/07/13@06:33:39.562-0500] P-17331 T-140515380281600 I WSAGENT32: (452) Login by mfg on batch.
[2026/07/13@06:33:39.563-0500] P-17322 T-139780878946560 I WSAGENT33: (452) Login by mfg on batch.
[2026/07/13@06:33:39.564-0500] P-17339 T-140297703747840 I WSAGENT28: (7129) Usr 28 set name to mfg.
[2026/07/13@06:33:39.564-0500] P-17326 T-140587959419136 I WSAGENT30: (7129) Usr 30 set name to mfg.
[2026/07/13@06:33:39.565-0500] P-17340 T-139962508124416 I WSAGENT31: (7129) Usr 31 set name to mfg.
[2026/07/13@06:33:39.566-0500] P-17322 T-139780878946560 I WSAGENT33: (7129) Usr 33 set name to mfg.
[2026/07/13@06:33:39.572-0500] P-17345 T-139808252387584 I WSAGENT34: (452) Login by mfg on batch.
[2026/07/13@06:33:39.573-0500] P-17334 T-140710392152320 I WSAGENT29: (7129) Usr 29 set name to mfg.
[2026/07/13@06:33:39.576-0500] P-17345 T-139808252387584 I WSAGENT34: (7129) Usr 34 set name to mfg.
[2026/07/13@06:33:39.586-0500] P-17331 T-140515380281600 I WSAGENT32: (7129) Usr 32 set name to mfg.
[2026/07/13@06:33:39.593-0500] P-17351 T-140309285871872 I WSAGENT35: (452) Login by mfg on batch.
[2026/07/13@06:33:39.599-0500] P-17351 T-140309285871872 I WSAGENT35: (7129) Usr 35 set name to mfg.
[2026/07/13@06:33:39.835-0500] P-17326 T-140587959419136 I WSAGENT30: (-----) Received RECONNECT from WTB
[2026/07/13@06:33:39.835-0500] P-17331 T-140515380281600 I WSAGENT32: (-----) Received RECONNECT from WTB
[2026/07/13@06:33:39.837-0500] P-17340 T-139962508124416 I WSAGENT31: (-----) Received RECONNECT from WTB
[2026/07/13@06:33:39.838-0500] P-17338 T-140657448198400 I WSAGENT26: (-----) Received RECONNECT from WTB
[2026/07/13@06:33:39.841-0500] P-17334 T-140710392152320 I WSAGENT29: (-----) Received RECONNECT from WTB
[2026/07/13@06:33:39.842-0500] P-17339 T-140297703747840 I WSAGENT28: (-----) Received RECONNECT from WTB
[2026/07/13@06:33:39.845-0500] P-17322 T-139780878946560 I WSAGENT33: (-----) Received RECONNECT from WTB
[2026/07/13@06:33:39.849-0500] P-17345 T-139808252387584 I WSAGENT34: (-----) Received RECONNECT from WTB
[2026/07/13@06:33:39.894-0500] P-17351 T-140309285871872 I WSAGENT35: (-----) Received RECONNECT from WTB
[2026/07/13@06:33:40.563-0500] P-17354 T-140209112129792 I WSAGENT36: (452) Login by mfg on batch.
[2026/07/13@06:33:40.566-0500] P-17354 T-140209112129792 I WSAGENT36: (7129) Usr 36 set name to mfg.
[2026/07/13@06:33:40.790-0500] P-17354 T-140209112129792 I WSAGENT36: (-----) Received RECONNECT from WTB
[2026/07/13@06:34:23.321-0500] P-17605 T-139854071501248 I WDOG 21: (2527) Disconnecting dead user 27.
[2026/07/13@06:34:51.106-0500] P-17611 T-140394007668160 I AIMGT 22: (3777) Switched to ai extent /ai/prod/ipurch/ipurchprod.a2.
[2026/07/13@06:34:51.106-0500] P-17611 T-140394007668160 I AIMGT 22: (3778) This is after-image file number 213818 since the last AIMAGE BEGIN
[2026/07/13@06:34:56.114-0500] P-17611 T-140394007668160 I AIMGT 22: (13199) After-image extent /ai/prod/ipurch/ipurchprod.a1 has been copied to /backup/prod/aiarch/ipurch/db~prod~ipurch~ipurchprod.20200606.062533.00213817.ipurchprod.a1.
[2026/07/13@06:34:56.115-0500] P-17611 T-140394007668160 I AIMGT 22: (3789) Marked after-image extent /ai/prod/ipurch/ipurchprod.a1 EMPTY.

Mon Jul 13 06:35:46 2026
[2026/07/13@06:35:46.082-0500] P-17618 T-140465072349632 I APW 0: (2519) Disconnected.
[2026/07/13@06:35:46.082-0500] P-17618 T-140465072349632 I APW 0: (-----) user #: 0, usrinuse #: 0, (srvctl:srvctl) 0:0, latchId: 18
[2026/07/13@06:35:46.082-0500] P-17618 T-140465072349632 F APW 0: (-----) lock stack corrupt expected 18 was 0 sp 0
[2026/07/13@06:35:46.083-0500] P-17618 T-140465072349632 I APW 0: (439) ** Save file named core for analysis by Progress Software Corporation.
[2026/07/13@06:35:46.094-0500] P-17615 T-139779634287040 I BIW 0: (2520) Stopped.
[2026/07/13@06:35:46.103-0500] P-17612 T-139810855203264 I AIW 0: (-----) user #: 0, usrinuse #: 0, (srvctl:srvctl) 0:0, latchId: 14, bot: 1
[2026/07/13@06:35:46.104-0500] P-17612 T-139810855203264 F AIW 0: (-----) lock stack underflow 0
[2026/07/13@06:35:46.104-0500] P-17612 T-139810855203264 I AIW 0: (439) ** Save file named core for analysis by Progress Software Corporation.
[2026/07/13@06:35:46.119-0500] P-17611 T-140394007668160 I AIMGT 0: (2519) Disconnected.
[2026/07/13@11:35:46.000+0000] P-17354 T-140209112129792 I WSAGENT 0: (49) SYSTEM ERROR: Memory violation.
[2026/07/13@11:35:46.000+0000] P-17354 T-140209112129792 I WSAGENT 0: (439) ** Save file named core for analysis by Progress Software Corporation.
[2026/07/13@11:35:46.000+0000] P-17354 T-140209112129792 I WSAGENT 0: (-----) Generating /apps/ipurchase/work/webspeed/agents/protrace.17354
[2026/07/13@06:35:46.576-0500] P-17600 T-140099396777792 I BROKER 0: (15192) The database will complete shutdown within approximately 60 seconds.
[2026/07/13@06:35:46.577-0500] P-17600 T-140099396777792 I BROKER 0: (2249) Begin ABNORMAL shutdown code 2
[2026/07/13@06:35:53.324-0500] P-17605 T-139854071501248 I WDOG 0: (2519) Disconnected.

Mon Jul 13 11:36:53 2026
[2026/07/13@11:36:53.000+0000] P-17338 T-140657448198400 I WSAGENT 0: (49) SYSTEM ERROR: Memory violation.
[2026/07/13@11:36:53.000+0000] P-17338 T-140657448198400 I WSAGENT 0: (439) ** Save file named core for analysis by Progress Software Corporation.
[2026/07/13@11:36:53.000+0000] P-17338 T-140657448198400 I WSAGENT 0: (-----) Generating /apps/ipurchase/work/webspeed/agents/protrace.17338
 
Did you check the protrace files?

/apps/ipurchase/work/webspeed/agents/protrace.12422
/apps/ipurchase/work/webspeed/agents/protrace.11762
/apps/ipurchase/work/webspeed/agents/protrace.17354
/apps/ipurchase/work/webspeed/agents/protrace.17338

> [2026/07/13@06:35:46.082-0500] P-17618 T-140465072349632 I APW 0: (-----) user #: 0, usrinuse #: 0, (srvctl:srvctl) 0:0, latchId: 18

latchId: 18 = BFP - online backup queue latch.
Was the online backup running at that time?
 
Code: 
[2026/07/13@06:19:46.015-0500] P-17611 T-140394007668160 I AIMGT 22: (3778) This is after-image file number 213817 since the last AIMAGE BEGIN
[2026/07/13@06:19:51.016-0500] P-17611 T-140394007668160 I AIMGT 22: (13199) After-image extent /ai/prod/ipurch/ipurchprod.a6 has been copied to /backup/prod/aiarch/ipurch/db~prod~ipurch~ipurchprod.20200606.062533.00213816.ipurchprod.a6.
[snip]
[2026/07/13@06:32:32.000-0500] First Memory violation.
[snip]
[2026/07/13@06:34:51.106-0500] P-17611 T-140394007668160 I AIMGT 22: (3777) Switched to ai extent /ai/prod/ipurch/ipurchprod.a2.
[2026/07/13@06:34:51.106-0500] P-17611 T-140394007668160 I AIMGT 22: (3778) This is after-image file number 213818 since the last AIMAGE BEGIN
[2026/07/13@06:34:56.114-0500] P-17611 T-140394007668160 I AIMGT 22: (13199) After-image extent /ai/prod/ipurch/ipurchprod.a1 has been copied to /backup/prod/aiarch/ipurch/db~prod~ipurch~ipurchprod.20200606.062533.00213817.ipurchprod.a1.

You're switching ai files every 15 minutes. The first memory violation occurred 2 minutes before the current ai file was archived. What are the latest timestamps in its scan?
 
Hi George,

Yes, I checked protrace.12422. It was a WebSpeed _progres -web agent for ipurchprod_ws. The stack shows:

parse_form_encoded
WebCgiInit
webRunDispatcher
wvRunDispatcher

ABL stack points to:

src/web/objects/web-disp.p at line 775
tptstart-new.p at line 905

I also found in ipurchprod_ws.server.log that PID 12422 received many invalid/blank-token requests just before the crash, with scanner-like paths such as wp-admin, index.php, api, ReportServer, geoserver, and Admin/login.php.

At 06:32:32, the same PID crashed with:

SYSTEM ERROR: Memory violation (49)

and disconnected from DB user number 28.

Regarding online backup: I checked the backup location and the backup does not appear to have been running at the DB crash time around 06:35:46. Our daily backup appears to start around 18:00 server time. Evidence from /backup/proddb:

-rw-r--r-- 1 mfg qad 2266 Jul 13 18:00 ipurchprod.st
-rw-r--r-- 1 mfg qad 7027225671 Jul 13 18:01 ipurchprod.bkup.gz
-rw-r--r-- 1 mfg qad 8781157376 Jul 13 18:01 ipurchprod.bkup

Current server time check:

Tue 14 Jul 2026 04:20:49 AM CDT

So based on these timestamps, the backup activity was around 18:00, not around 06:35. I will still check DB log/job logs for BACKUP/probkup entries around 06:30-06:36 to confirm.

For the AI scan, I decompressed AI 213817 and 213818 to /tmp:

/tmp/ai_213817.a1
/tmp/ai_213818.a2

But rfutil scan against the live DB failed with:

** The database /db/prod/ipurch/ipurchprod is in use in multi-user mode. (276)

So I cannot scan using the live production DB while it is online.

Current finding so far: the first clear failure appears to be WebSpeed agent PID 12422 receiving repeated invalid/blank-token requests and then crashing with memory violation at 06:32:32. After multiple WebSpeed memory violations, APW/AIW later reported lock stack corrupt/underflow and broker initiated abnormal shutdown code 2.

Thanks.
 
Mike said:
** The database /db/prod/ipurch/ipurchprod is in use in multi-user mode. (276)

So I cannot scan using the live production DB while it is online.
Click to expand...
Code: 
prodb empty empty
rfutil empty -C aimage truncate -aiblocksize <your-db-ai-blocksize>
rfutil empty -C aimage scan verbose -a <ai-name> > scan.txt

> APW/AIW later reported lock stack corrupt/underflow and broker initiated abnormal shutdown code 2.

The structures in shared memory were already corrupted before these errors. All processed had "forgot" their numbers - the part of (or the entire?) Connection Table was zeroed out..
 
OpenEdge Release 11.7.9 build

OS: Linux Debian

Hi George / Rob,

I created a dummy database in /tmp and scanned the copied AI files successfully.

Production DB AI block size:

AI block size: 16384

Dummy DB steps used:

cd /tmp/aiscan_ipurch
prodb aiscan empty
rfutil aiscan -C aimage truncate -aiblocksize 16

Then scanned the copied AI files:

rfutil aiscan -C aimage scan verbose -a /tmp/ai_213817.a1 > /tmp/ai_213817_scan_verbose.out 2>&1
rfutil aiscan -C aimage scan verbose -a /tmp/ai_213818.a2 > /tmp/ai_213818_scan_verbose.out 2>&1

AI 213817 scan result:

Latest timestamp seen in the tail output:

Mon Jul 13 06:34:08 2026

Summary:

12195 notes were processed.
0 in-flight transactions.
211 transactions were started.
211 transactions were completed.
At the end of the .ai file, 0 transactions were still active.

AI 213818 scan result:

Latest timestamp seen in the tail output:

Mon Jul 13 07:25:01 2026

Summary:

178 notes were processed.
0 in-flight transactions.
25 transactions were started.
25 transactions were completed.
At the end of the .ai file, 0 transactions were still active.

So from the AI scan output, both AI files completed cleanly with 0 in-flight / 0 active transactions at the end.

Regarding online backup, it does not appear to have been running at the crash time around 06:35:46. Backup files show activity around 18:00/18:01 server time, not around 06:35.

Current finding so far:

The first clear failure was WebSpeed agent PID 12422 receiving repeated invalid/blank-token requests and then crashing with SYSTEM ERROR: Memory violation (49) at 06:32:32. After multiple WebSpeed memory violations, APW/AIW later reported lock stack corrupt/underflow and the broker initiated abnormal shutdown code 2.

Thanks.
 
The latest update to release 11.7 is 11.7.22. So you are missing 13 updates worth of bugs fixes. This is also the last update, since release 11.7 is retired since April 2025.

I strongly suggest that you test and implement 11.7.22.
 
You hit a Progress bug in a shared memory client, some data structures in database shared memory were corrupted, and various processes hit fatal errors and stopped. The database performed an abnormal shutdown to protect data integrity. That might be as much root cause as you ever get.

And it is much more likely to happen to you again if you don't patch your system. 11.7.9 is over five and a half years old.
 
Mike said:
AI 213817 scan result:

Latest timestamp seen in the tail output:

Mon Jul 13 06:34:08 2026
Click to expand...
In other words, transaction activity continued after the memory violation errors. Latches 14 and 18 were not permanently locked. Hence the corresponding error messages are not part of the root cause.
 
George Potemkin said:
In other words, transaction activity continued after the memory violation errors. Latches 14 and 18 were not permanently locked. Hence the corresponding error messages are not part of the root cause.
Click to expand...
Hi George ,

So what was the cause ? which user was responsible? and how to avoid in future?

Thanks
Mike
 
Mike said:
So what was the cause ? which user was responsible? and how to avoid in future?
Click to expand...
It's very difficult to answer these questions for memory violation errors. Strictly speaking, it's not an error, but a consequence of an error. The bug caused an access to an invalid address. As a result, the code received or modified invalid data. This will continue until the invalid address goes beyond the process's address space and then Progress issues the error message. The same bug may sometimes crash a database but othertimes it does not.

To find the root cause of the memory violation error, you need to meticulously collect data on all instances of this error and look for common patterns. It's like a hunting for a maniac.

And I completely agree with Rob Fitzpatrick: the best thing to do in this situation is to install the latest service pack.
 
As Rob has said, error 49 (almost) always points to a Progress bug. I know that there are a number of bugs that cause error 49 in 11.7 that have been fixed in later patch versions. I know because I raised them myself. As Rob says, you'll probably not get much more than this in terms of root cause analysis. Patching to 11.7.22 and planning the migration to 12.x is the solution.
 
You must log in or register to reply here.

Similar threads

Mike
  • Locked
Error Request for Progress Review – ipurch DB Abnormal Shutdown with WebSpeed Memory Violation and APW/AIW Lock Stack Errors
Replies
0
Views
41
Mike
Mike
Back
Top