Listener deployment threads getting hung before deployment is complete

Every once in awhile a deployment thread is getting stuck. This leaves the order in processing state and also is making one listener thread unusable. The request that's getting hung is not completing.

More investigation is needed to get to the bottom of this but so far it's been seen after trademark errors are returned from google - near a keyword exemption request is made to google and near a text ad exemption request is made to google. Can't tell yet if it's happening during the exemption request, before it, or in between multiple requests.

The expected result (obviously) is for the deployment requests to complete and not stay in processing.

I've been able to reproduce consistently with a merchant with 1 BA and 4 TLs, whose BA has a single editorial error.

======================================================================================

// prescriptions trademark error
// there is nothing in the log for the customer after the exemption request is made:

2013-11-04 17:00:16.899 (3) [pool-6-thread-4]: KeywordDAO(accountID 16) DB updates: 2 items updated, 2 pending changes deleted, 0 pending updates deleted, 2 errors cleared
2013-11-04 17:00:16.900 (3) [pool-6-thread-1]: Non-trademark error found. Code=[0]. Error Text=[prescriptions]. Field=[operations[11].operand.criterion.text]. Trigger=[prescriptions]
2013-11-04 17:00:16.900 (3) [pool-6-thread-1]: Non-trademark error found. Code=[0]. Error Text=[prescription]. Field=[operations[38].operand.criterion.text]. Trigger=[prescription]
2013-11-04 17:00:16.900 (2) [pool-6-thread-4]: Google Request Errors for accountID 16(KeywordChangeRequest)

Keyword: +contact +prescription
Type: Broad
Status: Active
id=35289, code=0: prescription(reason: CriterionPolicyError: externalPolicyName=Online pharmacy certification required(Your keyword list appears to contain pharmacy-related content. Google policy requires online pharmacies* in the U.S. to be accredited by the National Association Boards of Pharmacy. Additionally, these pharmacies may only target ads to users in the country in which they are accredited.
<p>
<p>
The AdWords program is only open to pharmacies based in the U.S. or Canada. Google policy does not allow AdWords ads for prescription drugs to be displayed in other countries.
<p>
<p>
For more information about the National Association Boards of Pharmacy, please visit www.nabp.net.
<p>
<p>
*Pharmaceutical manufacturers cannot advertise pharmaceutical drug branded campaigns, websites or keywords outside of the U.S. and Canada. This is also true for informational campaigns targeting physicians exclusively. Please update your location targeting settings to target the U.S. or Canada only.? – ), isExemptable=true, violatingParts[1]=[

{index=10, length=12}

], policyName=pharma, violatingText=[prescription])(isExemptable: true), trigger=prescription, field=operations[13].operand.criterion.text

Keyword: +contact +prescriptions
Type: Broad
Status: Active
id=35290, code=0: prescriptions(reason: CriterionPolicyError: externalPolicyName=Online pharmacy certification required(Your keyword list appears to contain pharmacy-related content. Google policy requires online pharmacies* in the U.S. to be accredited by the National Association Boards of Pharmacy. Additionally, these pharmacies may only target ads to users in the country in which they are accredited.
<p>
<p>
The AdWords program is only open to pharmacies based in the U.S. or Canada. Google policy does not allow AdWords ads for prescription drugs to be displayed in other countries.
<p>
<p>
For more information about the National Association Boards of Pharmacy, please visit www.nabp.net.
<p>
<p>
*Pharmaceutical manufacturers cannot advertise pharmaceutical drug branded campaigns, websites or keywords outside of the U.S. and Canada. This is also true for informational campaigns targeting physicians exclusively. Please update your location targeting settings to target the U.S. or Canada only.? – ), isExemptable=true, violatingParts[1]=[

{index=10, length=13}

], policyName=pharma, violatingText=[prescriptions])(isExemptable: true), trigger=prescriptions, field=operations[49].operand.criterion.text
2013-11-04 17:00:16.901 (3) [pool-6-thread-4]: KeywordChangeRequest (accountID 16): Sending 63 add requests
2013-11-04 17:00:17.354 (3) [pool-6-thread-2]: Non-trademark error found. Code=[0]. Error Text=[prescription]. Field=[operations[24].operand.criterion.text]. Trigger=[prescription]
2013-11-04 17:00:17.354 (3) [pool-6-thread-2]: Non-trademark error found. Code=[0]. Error Text=[prescriptions]. Field=[operations[62].operand.criterion.text]. Trigger=[prescriptions]
2013-11-04 17:00:17.361 (3) [pool-6-thread-6]: KeywordDAO(accountID 16) Request contained 2 adds, 0 updates, 0 deletes.
2013-11-04 17:00:17.361 (3) [pool-6-thread-6]: KeywordDAO(accountID 16) DB updates: 2 items updated, 2 pending changes deleted, 0 pending updates deleted, 0 errors cleared
2013-11-04 17:00:39.642 (3) [Thread-9]: Heartbeat #801 (1383584439631) received in 0.011s
2013-11-04 17:01:09.644 (3) [Thread-9]: Heartbeat #802 (1383584469631) received in 0.013s
2013-11-04 17:01:39.642 (3) [Thread-9]: Heartbeat #803 (1383584499631) received in 0.011s
2013-11-04 17:02:09.643 (3) [Thread-9]: Heartbeat #804 (1383584529631) received in 0.012s
2013-11-04 17:02:39.642 (3) [Thread-9]: Heartbeat #805 (1383584559631) received in 0.011s
2013-11-04 17:03:09.643 (3) [Thread-9]: Heartbeat #806 (1383584589631) received in 0.012s
2013-11-04 17:03:39.638 (3) [Thread-9]: Heartbeat #807 (1383584619630) received in 0.008s
2013-11-04 17:04:09.643 (3) [Thread-9]: Heartbeat #808 (1383584649631) received in 0.012s
2013-11-04 17:04:39.642 (3) [Thread-9]: Heartbeat #809 (1383584679631) received in 0.011s
2013-11-04 17:05:09.643 (3) [Thread-9]: Heartbeat #810 (1383584709631) received in 0.012s
2013-11-04 17:05:39.642 (3) [Thread-9]: Heartbeat #811 (1383584739631) received in 0.011s
2013-11-04 17:06:09.643 (3) [Thread-9]: Heartbeat #812 (1383584769631) received in 0.012s
2013-11-04 17:06:39.642 (3) [Thread-9]: Heartbeat #813 (1383584799631) received in 0.011s

======================================================================================

This appears to have happened before on Duda Mobile. The listener normally restarts at 10:20 UTC but there are a couple of listener logs (like 2013-11-05-102001) that are started at 12:25 UTC. There is code that will wait up to 2 hours before shutting down if there are incomplete processes, like in this case. Here's the info JB got for me from aml7:

[TSAApp@aml7-core1 tsa-admax-jmslistener]$ ls -l
total 9748
rw-rr- 1 TSAApp tsaapp 211736 Nov 5 19:51 tsa-admax-jmslistener.log
rw-rr- 1 TSAApp tsaapp 549829 Oct 16 21:44 tsa-admax-jmslistener.log.2013-10-16-214406
rw-rr- 1 TSAApp tsaapp 350677 Oct 17 22:05 tsa-admax-jmslistener.log.2013-10-17-220517
rw-rr- 1 TSAApp tsaapp 93944 Oct 18 01:17 tsa-admax-jmslistener.log.2013-10-18-011721
rw-rr- 1 TSAApp tsaapp 162386 Oct 18 10:20 tsa-admax-jmslistener.log.2013-10-18-102001
rw-rr- 1 TSAApp tsaapp 341744 Oct 19 10:20 tsa-admax-jmslistener.log.2013-10-19-102001
rw-rr- 1 TSAApp tsaapp 304350 Oct 20 10:20 tsa-admax-jmslistener.log.2013-10-20-102001
rw-rr- 1 TSAApp tsaapp 331418 Oct 21 10:20 tsa-admax-jmslistener.log.2013-10-21-102001
rw-rr- 1 TSAApp tsaapp 304350 Oct 22 10:20 tsa-admax-jmslistener.log.2013-10-22-102001
rw-rr- 1 TSAApp tsaapp 304349 Oct 23 10:20 tsa-admax-jmslistener.log.2013-10-23-102001
rw-rr- 1 TSAApp tsaapp 220808 Oct 23 22:02 tsa-admax-jmslistener.log.2013-10-23-220413
rw-rr- 1 TSAApp tsaapp 74981 Oct 23 23:24 tsa-admax-jmslistener.log.2013-10-23-232441
rw-rr- 1 TSAApp tsaapp 141737 Oct 24 10:20 tsa-admax-jmslistener.log.2013-10-24-102001
rw-rr- 1 TSAApp tsaapp 312325 Oct 25 10:20 tsa-admax-jmslistener.log.2013-10-25-102001
rw-rr- 1 TSAApp tsaapp 387719 Oct 26 10:20 tsa-admax-jmslistener.log.2013-10-26-102001
rw-rr- 1 TSAApp tsaapp 304328 Oct 27 10:20 tsa-admax-jmslistener.log.2013-10-27-102001
rw-rr- 1 TSAApp tsaapp 304328 Oct 28 10:20 tsa-admax-jmslistener.log.2013-10-28-102001
rw-rr- 1 TSAApp tsaapp 1548441 Oct 29 00:39 tsa-admax-jmslistener.log.2013-10-29-003927
rw-rr- 1 TSAApp tsaapp 126306 Oct 29 10:20 tsa-admax-jmslistener.log.2013-10-29-102001
rw-rr- 1 TSAApp tsaapp 304328 Oct 30 10:20 tsa-admax-jmslistener.log.2013-10-30-102001
rw-rr- 1 TSAApp tsaapp 999903 Oct 31 12:25 tsa-admax-jmslistener.log.2013-10-31-102001
rw-rr- 1 TSAApp tsaapp 386329 Nov 1 10:20 tsa-admax-jmslistener.log.2013-11-01-102001
rw-rr- 1 TSAApp tsaapp 304328 Nov 2 10:20 tsa-admax-jmslistener.log.2013-11-02-102001
rw-rr- 1 TSAApp tsaapp 304328 Nov 3 10:20 tsa-admax-jmslistener.log.2013-11-03-102001
rw-rr- 1 TSAApp tsaapp 421856 Nov 4 10:20 tsa-admax-jmslistener.log.2013-11-04-102001
rw-rr- 1 TSAApp tsaapp 724136 Nov 5 12:25 tsa-admax-jmslistener.log.2013-11-05-102001
[TSAApp@aml7-core1 tsa-admax-jmslistener]$ date
Tue Nov 5 19:52:16 UTC 2013
[TSAApp@aml7-core1 tsa-admax-jmslistener]$ crontab -l
#sttart the listener every day at 12:20am
20 10 * * * /etc/init.d/tsa-admax-jmslistener.sh restart >> /tmp/tsa-admax-jmslistener.restart.log 2>&1

1. check every 5 minutes to make sure the listener is running, if it isn't, start it
   */5 * * * * /etc/init.d/tsa-admax-jmslistener.sh start >> /tmp/tsa-admax-jmslistener.start.log 2>&1

1. check listener for errors every minute
   */1 * * * * /usr/local/tsa/bidmgr/monitor-admax-listener.sh

#uncomment the three below when duda goes live
0 0 * * * /usr/local/tsa/bidmgr/crontab-wrapper.sh --script googlesyncmanagerusernames.sh -d3 -e 9157597277
00 12 * * * /usr/local/tsa/bidmgr/morning-data-process.sh --config-file /var/local/tsa/config/GoogleMCCReport.emails.txt
00 9 * * * /usr/local/tsa/bidmgr/crontab-wrapper.sh --script admax-process.sh -d3 --config-file /var/local/tsa/config/GoogleMCCReport.emails.txt

*/5 * * * * /usr/local/tsa/bidmgr/crontab-wrapper.sh --script dbreplicator_check.sh -d 3

[TSAApp@aml7-core1 tsa-admax-jmslistener]$

Checking that file from the 31st, you can see 7 deployments were requested but only 6 were complete:

less tsa-admax-jmslistener.log.2013-10-31-102001 | grep -c "Request added to map"
7
less tsa-admax-jmslistener.log.2013-10-31-102001 | grep -c "Request removed from map"
6

======================================================================================

// sparkle trademark error
// there is nothing in the log for the customer after the exemption request is made:

2013-10-30 19:38:55.030 (3) [pool-8-thread-3]: Caught recoverable API Error, retry #: 1
2013-10-30 19:38:55.415 (3) [pool-8-thread-2]: Non-trademark error found. Code=[0]. Error Text=[Sparkle]. Field=[operations[0].operand.ad.description1]. Trigger=[]
2013-10-30 19:38:55.415 (3) [pool-8-thread-2]: Non-trademark error found. Code=[0]. Error Text=[Sparkle]. Field=[operations[2].operand.ad.description2]. Trigger=[]
2013-10-30 19:38:55.426 (3) [pool-8-thread-3]: TextAdDAO(accountID 13): Inserted 2 Errors: Updated 2 pending changes, cleared 0 existing errors.
2013-10-30 19:38:55.432 (3) [pool-8-thread-3]: TextAdDAO(accountID 13) Request contained 2 adds, 0 updates, 0 deletes.
2013-10-30 19:38:55.433 (3) [pool-8-thread-3]: TextAdDAO(accountID 13) DB updates: 2 items updated, 2 pending changes deleted, 0 pending updates deleted, 0 errors cleared
2013-10-30 19:39:10.362 (3) [Thread-9]: Heartbeat #1118 (1383161950347) received in 0.014s
2013-10-30 19:39:40.359 (3) [Thread-9]: Heartbeat #1119 (1383161980347) received in 0.012s
2013-10-30 19:40:10.368 (3) [Thread-9]: Heartbeat #1120 (1383162010347) received in 0.021s
2013-10-30 19:40:10.424 (3) [pool-4-thread-2]: No new jobs to execute for type: [1,2]
2013-10-30 19:40:12.348 (3) [pool-4-thread-1]: No new jobs to execute for type: [4]
2013-10-30 19:40:14.353 (3) [pool-4-thread-1]: No new jobs to execute for type: [6]
2013-10-30 19:40:40.378 (3) [Thread-9]: Heartbeat #1121 (1383162040347) received in 0.031s
2013-10-30 19:41:10.361 (3) [Thread-9]: Heartbeat #1122 (1383162070347) received in 0.014s
2013-10-30 19:41:40.361 (3) [Thread-9]: Heartbeat #1123 (1383162100347) received in 0.014s
2013-10-30 19:42:10.362 (3) [Thread-9]: Heartbeat #1124 (1383162130347) received in 0.015s
2013-10-30 19:42:40.358 (3) [Thread-9]: Heartbeat #1125 (1383162160347) received in 0.011s