[LDM #RHW-703095]: Errors: "Upstream LDM says we're not allowed to receive requested products"

James,

Are you two LDM hosts behind a Network Address Translation (NAT) device? If so, 
then the upstream LDM will see the identical requests as coming from the same 
IP address (that of the NAT device) and disallow one of them at a time.

> Hi,
> 
> I am trying to acquire products from another institution and have set up a new
> LDM client to do so. However, my LDM is getting errors of the form "ERROR:
> Disconnecting due to LDM failure; Upstream LDM says we're not allowed to 
> receive
> requested products". These errors and disconnections occur roughly every two
> minutes for each REQUEST line I have. The odd part is that we do get the
> products we requested, despite the errors.
> 
> Here are the details:
> 
> LDM client:  129.55.66.6 (llwxldm1) @ MIT LL, version 6.6.5
> LDM servers: 128.117.201.208 @ NCAR & 128.117.201.209 @ NCAR
> 
> Both LDMs are newly set up. However, we exchange files with NCAR quite a bit
> through other existing LDMs with no problems.
> 
> My LDM client has two REQUEST lines for each of the two NCAR servers. My
> understanding was that these errors perhaps relate to duplicate or overlapping
> requests so I tightened up the Regular Expressions quite a bit more than I
> usually do. Here are the REQUEST lines:
> 
> request EXP  ^ncar\.ral\.CoSPA\.Live\.Hrrr(lVil|EchoTops)\..*T.*\.PT.*\.nc$
> 128.117.201.208:388
> request EXP  ^ncar\.ral\.CoSPA\.Live\.Hrrr(lVil|EchoTops)\..*T.*\.PT.*\.nc$
> 128.117.201.209:388
> request EXP
> ^ncar\.ral\.CoSPA\.Live\.BlendNcarPc(DigitalVil|EchoTops)\..*T.*\.PT.*\.nc$
> 128.117.201.208:388
> request EXP
> ^ncar\.ral\.CoSPA\.Live\.BlendNcarPc(DigitalVil|EchoTops)\..*T.*\.PT.*\.nc$
> 128.117.201.209:388
> 
> Each of these lines repeatedly produces a corresponding error/disconnection, 
> for
> example:
> 
> Jul 18 18:45:36 llwxldm1 128.117.201.208[15399] ERROR: Disconnecting due to 
> LDM
> failure; Upstream LDM says we're not allowed to receive requested products:
> 20130718183036.142 TS_ENDT {{EXP,
> "^ncar\.ral\.CoSPA\.Live\.Hrrr(lVil|EchoTops)\..*T.*\.PT.*\.nc$"},{NONE,
> "SIG=cc94a8a3823bbe68a4598cc62bd6b26c"}}
> Jul 18 18:51:36 llwxldm1 128.117.201.209[15400] ERROR: Disconnecting due to 
> LDM
> failure; Upstream LDM says we're not allowed to receive requested products:
> 20130718183636.159 TS_ENDT {{EXP,
> "^ncar\.ral\.CoSPA\.Live\.Hrrr(lVil|EchoTops)\..*T.*\.PT.*\.nc$"},{NONE,
> "SIG=e45193be67054c0b86ccd5764e1b018e"}}
> Jul 18 18:55:16 llwxldm1 128.117.201.208[15397] ERROR: Disconnecting due to 
> LDM
> failure; Upstream LDM says we're not allowed to receive requested products:
> 20130718184015.874 TS_ENDT {{EXP,
> "^ncar\.ral\.CoSPA\.Live\.BlendNcarPc(DigitalVil|EchoTops)\..*T.*\.PT.*\.nc$"},{NONE,
> "SIG=6bef0984832714e8ff5fa65e95491264"}}
> Jul 18 18:56:46 llwxldm1 128.117.201.209[15398] ERROR: Disconnecting due to 
> LDM
> failure; Upstream LDM says we're not allowed to receive requested products:
> 20130718184146.006 TS_ENDT {{EXP,
> "^ncar\.ral\.CoSPA\.Live\.BlendNcarPc(DigitalVil|EchoTops)\..*T.*\.PT.*\.nc$"},{NONE,
> "SIG=26dc2457d7958a5b016a1021a058ff69"}}
> 
> However, we always receive the products we want from each server, for example:
> 
> Jul 18 18:46:16 llwxldm1 128.117.201.209[15400] INFO:   102508
> 20130718184557.926     EXP 000
> ncar.ral.CoSPA.Live.HrrrlVil.2013-07-18T17:00:00.PT05:30.nc
> Jul 18 18:46:16 llwxldm1 128.117.201.208[15399] INFO: comingsoon/blkdata:
> duplicate:   102508 20130718184557.926     EXP 000
> ncar.ral.CoSPA.Live.HrrrlVil.2013-07-18T17:00:00.PT05:30.nc
> Jul 18 18:52:55 llwxldm1 128.117.201.209[15398] INFO:    97429
> 20130718185233.547     EXP 000
> ncar.ral.CoSPA.Live.BlendNcarPcEchoTops.2013-07-18T18:45:00.PT00:15.nc
> Jul 18 18:52:55 llwxldm1 128.117.201.208[15397] INFO: comingsoon/blkdata:
> duplicate:    97429 20130718185233.547     EXP 000
> ncar.ral.CoSPA.Live.BlendNcarPcEchoTops.2013-07-18T18:45:00.PT00:15.nc
> Jul 18 18:53:55 llwxldm1 128.117.201.208[15397] INFO:   294947
> 20130718185318.425     EXP 000
> ncar.ral.CoSPA.Live.BlendNcarPcDigitalVil.2013-07-18T18:45:00.PT02:45.nc
> Jul 18 18:53:56 llwxldm1 128.117.201.209[15398] INFO: comingsoon/blkdata:
> duplicate:   294947 20130718185318.425     EXP 000
> ncar.ral.CoSPA.Live.BlendNcarPcDigitalVil.2013-07-18T18:45:00.PT02:45.nc
> Jul 18 18:57:27 llwxldm1 128.117.201.209[15400] INFO:   189556
> 20130718185712.336     EXP 000
> ncar.ral.CoSPA.Live.HrrrEchoTops.2013-07-18T17:00:00.PT07:30.nc
> Jul 18 18:58:00 llwxldm1 128.117.201.208[15399] INFO: comingsoon6: duplicate:
> 189556 20130718185712.336     EXP 000
> ncar.ral.CoSPA.Live.HrrrEchoTops.2013-07-18T17:00:00.PT07:30.nc
> 
> I've been working closely with Sue Dettling at the NCAR end and she turned on
> debugging in her LDM. She sent me her LDM server logs for a time period where 
> an
> error/disconnection occurred:
> 
> ldmd.log:Jul 10 00:57:14 cospa2 ldmd[19144] DEBUG: SO_SNDBUF 16384
> ldmd.log:Jul 10 00:57:14 cospa2 ldmd[19144] DEBUG: SO_SNDBUF 16384
> ldmd.log:Jul 10 00:57:14 cospa2 ldmd[19144] DEBUG: SO_RCVBUF 87380
> ldmd.log:Jul 10 00:57:14 cospa2 ldmd[19144] DEBUG: SO_RCVBUF 87380
> ldmd.log:Jul 10 00:57:14 cospa2 ldmd[19144] INFO: RPC buffer sizes for
> 129.55.66.6: send=16384; recv=87380
> ldmd.log:Jul 10 00:57:14 cospa2 ldmd[19144] INFO: RPC buffer sizes for
> 129.55.66.6: send=16384; recv=87380
> ldmd.log:Jul 10 00:57:14 cospa2 129.55.66.6[19144] INFO: Connection from 
> 129.55.66.6
> ldmd.log:Jul 10 00:57:14 cospa2 129.55.66.6[19144] INFO: Connection from 
> 129.55.66.6
> ldmd.log:Jul 10 00:57:14 cospa2 129.55.66.6[19144] INFO: Resolving 129.55.66.6
> to llwxldm1.WX.LL.MIT.EDU took 0.000327 seconds
> ldmd.log:Jul 10 00:57:14 cospa2 129.55.66.6[19144] INFO: Resolving 129.55.66.6
> to llwxldm1.WX.LL.MIT.EDU took 0.000327 seconds
> ldmd.log:Jul 10 00:57:14 cospa2 129.55.66.6[19144] DEBUG: hit EXP = EXP & EXP
> ldmd.log:Jul 10 00:57:14 cospa2 129.55.66.6[19144] DEBUG: hit EXP = EXP & EXP
> ldmd.log:Jul 10 00:57:14 cospa2 129.55.66.6[19144] NOTE: [uldb.c:1232] FEEDME
> request from 129.55.66.6 overlaps existing service: 
> request="20130710004214.101
> TS_ENDT {{EXP,
> "^ncar\.ral\.CoSPA\.Live\.Hrrr(lVil|EchoTops)\..*T.*\.PT.*\.nc$"}}",
> service="20130710003616.260 TS_ENDT {{EXP,
> "^ncar\.ral\.CoSPA\.Live\.Hrrr(lVil|EchoTops)\..*T.*\.PT.*\.nc$"}}"
> ldmd.log:Jul 10 00:57:14 cospa2 129.55.66.6[19144] NOTE: [uldb.c:1232] FEEDME
> request from 129.55.66.6 overlaps existing service: 
> request="20130710004214.101
> TS_ENDT {{EXP,
> "^ncar\.ral\.CoSPA\.Live\.Hrrr(lVil|EchoTops)\..*T.*\.PT.*\.nc$"}}",
> service="20130710003616.260 TS_ENDT {{EXP,
> "^ncar\.ral\.CoSPA\.Live\.Hrrr(lVil|EchoTops)\..*T.*\.PT.*\.nc$"}}"
> ldmd.log:Jul 10 00:57:14 cospa2 129.55.66.6[19144] NOTE: [ldm6_server.c:340]
> This upstream LDM process is disallowed
> ldmd.log:Jul 10 00:57:14 cospa2 129.55.66.6[19144] NOTE: [ldm6_server.c:340]
> This upstream LDM process is disallowed
> ldmd.log:Jul 10 00:57:14 cospa2 129.55.66.6[19144] INFO: Exiting
> ldmd.log:Jul 10 00:57:14 cospa2 129.55.66.6[19144] INFO: Exiting
> ldmd.log:Jul 10 00:57:14 cospa2 ldmd[11420] NOTE: child 19144 exited with 
> status 2
> ldmd.log:Jul 10 00:57:14 cospa2 ldmd[11420] NOTE: child 19144 exited with 
> status 2
> 
> I don't see how I am making duplicate or overlapping requests to either
> server. Do you have any idea what we may be doing wrong here?
> 
> Thanks for any light you can shine on this.
> 
> ---------------------------+---------------------------
> James M. Pelagatti (Jamie) | MIT Lincoln Laboratory
> Software Engineer        | Group 43 (Weather Sensing)
> (781) 981-1886           | 244 Wood St., Room S1-611
> FAX: (781) 981-0632      | Lexington, MA 02420-9108
> mailto:address@hidden  | http://www.ll.mit.edu

Regards,
Steve Emmerson

Ticket Details
===================
Ticket ID: RHW-703095
Department: Support LDM
Priority: Normal
Status: Closed