error TCP_SUB_WRITING

[LAWRENCE]

We have an outbound thread (for onbase sending encoded PDF’s), that every so often gets an ERROR and what shows in the log and errlog is “Write sub thread hung with status “TCP_SUB_WRITING” after a minute.”

We can cycle the process, and have the same message resent and it works.

We’re trying to figure out if this is something with the network connection, if it’s a process level resource issue, or some incorrect formatting of the encoded PDF, or, or, or… 🙂

Anyone have any suggestions how to troubleshoot ?

Topic

[Robert Kersemakers]

Could this be a firewall issue? Maybe the PDF/message is too large and the firewall will stop the connecting after x MB?
We once had this with an inbound ORU connecting where large ORU messages were interrupted after a certain amount of bytes. After a long search it was the firewall on the other side.

Can you see anything in the logs when you up the Engine Log Configuration?

Zuyderland Medisch Centrum; Heerlen/Sittard; The Netherlands

[Peter Heggie]

We had a similar issue with our firewall where certain file transfers were killed after X bytes, but only after the connection was quiesced. We had to upgrade our firewall.

Peter Heggie

[LAWRENCE]

We have our networking team, along with Onbase and Epic Interconnect reps, engaged with the troubleshooting.  I will ask our networking team to take another look at the firewall settings (they said they reviewed it, but I’ll pester them a little;)

 

Here is what is in the process log immediately after the message that fails:

[msg :Msg :INFO/0:to_t_conv_shp105:10/24/2023 08:42:57] [0.0.147050] Updating the recovery database
[dbi :rlog:INFO/1:to_t_conv_shp105:10/24/2023 08:42:57] [0.0.147050] Update msg in recovery db to state OB post-SMS
[dbi :log :DBUG/2:to_t_conv_shp105:10/24/2023 08:42:57] log context: type 1, dbn 1, msgRec 10001, mdRec 10002, bodyRec 10003
[dbi :log :DBUG/2:to_t_conv_shp105:10/24/2023 08:42:57] state 11, mode 1
[dbi :dbi :DBUG/1:to_t_conv_shp105:10/24/2023 08:42:57] (0) ‘cl_lock: Trying to lock database ‘
[dbi :dbi :DBUG/1:to_t_conv_shp105:10/24/2023 08:42:57] (0) ‘type=w, rec=10001
[dbi :dbi :DBUG/1:to_t_conv_shp105:–/–/—- –:–:–] ‘
[dbi :dbi :DBUG/1:to_t_conv_shp105:10/24/2023 08:42:57] (1) ‘type=w, rec=10002
[dbi :dbi :DBUG/1:to_t_conv_shp105:–/–/—- –:–:–] ‘
[dbi :dbi :DBUG/1:to_t_conv_shp105:10/24/2023 08:42:57] (2) ‘type=w, rec=10003
[dbi :dbi :DBUG/1:to_t_conv_shp105:–/–/—- –:–:–] ‘
[dbi :dbi :DBUG/1:to_t_conv_shp105:10/24/2023 08:42:57] (0) ‘cl_lock: Succeeded in locking database ‘
[dbi :log :DBUG/2:to_t_conv_shp105:10/24/2023 08:42:57] update var MD, upd 1, dirty 0
[diag:leak:DBUG/0:to_t_conv_shp105:10/24/2023 08:42:57] diag imh free 0x0x7fdfb480f390
[diag:leak:DBUG/0:to_t_conv_shp105:10/24/2023 08:42:57] diag ptm free 0x0x7fdfb47f5c50
[pti :sche:INFO/1:to_t_conv_shp105:10/24/2023 08:42:57] Thread has 1 ready events left.
[pd :thrd:INFO/1:to_t_conv_shp105:10/24/2023 08:42:57] OB-Data queue has 7 msgs
[pd :thrd:INFO/1:to_t_conv_shp105:10/24/2023 08:42:57] OB-Data queue has NO work
[pd :thrd:INFO/1:to_t_conv_shp105:10/24/2023 08:42:57] OB-Data queue has 7 msgs
[pd :thrd:INFO/1:to_t_conv_shp105:10/24/2023 08:42:57] OB-Data queue has NO work
[pd :thrd:INFO/1:to_t_conv_shp105:10/24/2023 08:42:57] OB-Data queue has 7 msgs
[pd :thrd:INFO/1:to_t_conv_shp105:10/24/2023 08:42:57] OB-Data queue has NO work
[pd :thrd:INFO/1:to_t_conv_shp105:10/24/2023 08:42:57] OB-Data queue has 7 msgs
[pd :thrd:INFO/1:to_t_conv_shp105:10/24/2023 08:42:57] OB-Data queue has NO work
[pd :thrd:INFO/1:to_t_conv_shp105:10/24/2023 08:42:57] OB-Data queue has 7 msgs
[pd :thrd:INFO/1:to_t_conv_shp105:10/24/2023 08:42:57] OB-Data queue has NO work
[pti :sche:DBUG/2:to_t_conv_shp105:10/24/2023 08:42:57] Thread 2 has been enabled
[pti :sche:INFO/1:to_t_conv_shp105:10/24/2023 08:42:57] Thread has 1 ready events.
[pti :even:DBUG/0:to_t_conv_shp105:10/24/2023 08:42:57] Processing SOCKET (TCP Client Read) event 0x0x7fdfac3e4490
[pti :even:DBUG/1:to_t_conv_shp105:10/24/2023 08:42:57] Calling cb 0x501c77
[tcp :wrte:WARN/0:to_t_conv_shp105:10/24/2023 08:43:12] Write sub thread hung with status “TCP_SUB_WRITING” after 15 seconds.
[tcp :wrte:WARN/0:to_t_conv_shp105:10/24/2023 08:43:27] Write sub thread hung with status “TCP_SUB_WRITING” after 15 seconds.
[tcp :wrte:WARN/0:to_t_conv_shp105:10/24/2023 08:43:42] Write sub thread hung with status “TCP_SUB_WRITING” after 15 seconds.
[tcp :wrte:WARN/0:to_t_conv_shp105:10/24/2023 08:43:57] Write sub thread hung with status “TCP_SUB_WRITING” after 15 seconds.
[pd :pdtd:INFO/1:to_t_conv_shp105:10/24/2023 08:43:57] Set driver status to PD_STATUS_ERROR
[tcp :wrte:ERR /0:to_t_conv_shp105:10/24/2023 08:43:57] Write sub thread hung with status “TCP_SUB_WRITING” after a minute.

[Peter Heggie]

I don’t know if our firewall issue is your issue, but I can tell you it was not a configuration issue, it was a bug in the firewall software, for a specific version of PaloAlto.

Peter Heggie

[Author]

Replies