Uploaded image for project: 'Help-Desk'
  1. Help-Desk
  2. HELP-13323

[fiware-stackoverflow] Notification from subscription does not notify specific domains

    Details

      Description

      Created question in FIWARE Q/A platform on 14-11-2017 at 13:11
      Please, ANSWER this question AT https://stackoverflow.com/questions/47286499/notification-from-subscription-does-not-notify-specific-domains

      Question:
      Notification from subscription does not notify specific domains

      Description:
      We are migrating from one pre-production platform on the cloud to another server. We have successfully migrated everything but something strange is happening with the subscriptions of Orion Context Broker, since our instance of Orion is successfully notifying different endpoints, but not the one from our platform.

      Both of the subscriptions are done from the same instance and implementing HTTPS, and the security groups are equally configured. The Orion context broker logs doesnt show any useful information about what is happening with the cURL request that internally is doing.

      Here is an example of a right subscription from this Orion:

      time=Tuesday 14 Nov 12:54:03 2017.102Z | lvl=INFO | corr=e42533b2-c93a-11e7-b333-0242ac110003 | trans=1510663280-019-00000000009 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=logMsg.h[1832]:lmTransactionStart | msg=Starting transaction from 54.194.53.34:48920/v1/updateContext
      time=Tuesday 14 Nov 12:54:03 2017.102Z | lvl=INFO | corr=e42533b2-c93a-11e7-b333-0242ac110003 | trans=1510663280-019-00000000009 | from=54.194.53.34 | srv=pending | subsrv=/howto | comp=Orion | op=rest.cpp[882]:servicePathSplit | msg=Service Path 0: '/howto'
      time=Tuesday 14 Nov 12:54:03 2017.103Z | lvl=INFO | corr=e42533b2-c93a-11e7-b333-0242ac110003 | trans=1510663280-019-00000000009 | from=54.194.53.34 | srv=howtoservice | subsrv=/howto | comp=Orion | op=connectionOperations.cpp[92]:collectionQuery | msg=Database Operation Successful (query: { _id.id: "M1111", _id.type: "Thing", _id.servicePath:

      { $in: [ /^/howto$/ ] }

      })
      time=Tuesday 14 Nov 12:54:03 2017.104Z | lvl=INFO | corr=e42533b2-c93a-11e7-b333-0242ac110003 | trans=1510663280-019-00000000009 | from=54.194.53.34 | srv=howtoservice | subsrv=/howto | comp=Orion | op=connectionOperations.cpp[447]:collectionUpdate | msg=Database Operation Successful (update: <{ _id.id: "M1111", _id.type: "Thing", _id.servicePath:

      { $in: [ /^/howto$/ ] }

      }, { $set: { attrs.local: { value: "1.1.1.1,50", type: "string", md: { TimeInstant:

      { type: "ISO8601", value: "2017-11-14T12:54:03.090Z" }

      }, mdNames: [ "TimeInstant" ], creDate: 1510662361, modDate: 1510664043 }, attrs.serial_number: { value: "M1111", type: "string", md: { TimeInstant:

      { type: "ISO8601", value: "2017-11-14T12:54:03.090Z" }

      }, mdNames: [ "TimeInstant" ], creDate: 1510662361, modDate: 1510664043 }, attrs.TimeInstant:

      { value: "2017-11-14T12:54:03.090Z", type: "ISO8601", mdNames: [], creDate: 1510662361, modDate: 1510664043 }

      , modDate: 1510664043, lastCorrelator: "e42533b2-c93a-11e7-b333-0242ac110003" }, $unset:

      { location: 1 }

      }>)
      time=Tuesday 14 Nov 12:54:03 2017.104Z | lvl=INFO | corr=e42533b2-c93a-11e7-b333-0242ac110003 | trans=1510663280-019-00000000009 | from=54.194.53.34 | srv=howtoservice | subsrv=/howto | comp=Orion | op=logMsg.h[1916]:lmTransactionEnd | msg=Transaction ended
      time=Tuesday 14 Nov 12:54:03 2017.105Z | lvl=INFO | corr=N/A | trans=1510663280-019-00000000010 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=logMsg.h[1832]:lmTransactionStart | msg=Starting transaction to https://visualfy.secmotic.com:443/api/v1/devices/orion/local
      time=Tuesday 14 Nov 12:54:03 2017.105Z | lvl=INFO | corr=N/A | trans=1510663280-019-00000000010 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=httpRequestSend.cpp[599]:httpRequestSendWithCurl | msg=Sending message 2 to HTTP server: sending message of 540 bytes to HTTP server
      time=Tuesday 14 Nov 12:54:03 2017.238Z | lvl=INFO | corr=N/A | trans=1510663280-019-00000000010 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=httpRequestSend.cpp[620]:httpRequestSendWithCurl | msg=Notification Successfully Sent to https://visualfy.secmotic.com:443/api/v1/devices/orion/local
      time=Tuesday 14 Nov 12:54:03 2017.239Z | lvl=INFO | corr=N/A | trans=1510663280-019-00000000010 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=logMsg.h[1916]:lmTransactionEnd | msg=Transaction ended

      And here is an example of a failed notification.

      time=Tuesday 14 Nov 12:55:13 2017.809Z | lvl=INFO | corr=0e4a4e20-c93b-11e7-957f-0242ac110003 | trans=1510663280-019-00000000012 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=logMsg.h[1832]:lmTransactionStart | msg=Starting transaction from 54.194.53.34:48922/v1/updateContext
      time=Tuesday 14 Nov 12:55:13 2017.810Z | lvl=INFO | corr=0e4a4e20-c93b-11e7-957f-0242ac110003 | trans=1510663280-019-00000000012 | from=54.194.53.34 | srv=pending | subsrv=/howto | comp=Orion | op=rest.cpp[882]:servicePathSplit | msg=Service Path 0: '/howto'
      time=Tuesday 14 Nov 12:55:13 2017.810Z | lvl=INFO | corr=0e4a4e20-c93b-11e7-957f-0242ac110003 | trans=1510663280-019-00000000012 | from=54.194.53.34 | srv=howtoservice | subsrv=/howto | comp=Orion | op=connectionOperations.cpp[92]:collectionQuery | msg=Database Operation Successful (query: { _id.id: "M1111", _id.type: "Thing", _id.servicePath:

      { $in: [ /^/howto$/ ] }

      })
      time=Tuesday 14 Nov 12:55:13 2017.811Z | lvl=INFO | corr=0e4a4e20-c93b-11e7-957f-0242ac110003 | trans=1510663280-019-00000000012 | from=54.194.53.34 | srv=howtoservice | subsrv=/howto | comp=Orion | op=connectionOperations.cpp[447]:collectionUpdate | msg=Database Operation Successful (update: <{ _id.id: "M1111", _id.type: "Thing", _id.servicePath:

      { $in: [ /^/howto$/ ] }

      }, { $set: { attrs.local: { value: "1.1.1.1,50", type: "string", md: { TimeInstant:

      { type: "ISO8601", value: "2017-11-14T12:55:13.800Z" }

      }, mdNames: [ "TimeInstant" ], creDate: 1510662361, modDate: 1510664113 }, attrs.serial_number: { value: "M1111", type: "string", md: { TimeInstant:

      { type: "ISO8601", value: "2017-11-14T12:55:13.800Z" }

      }, mdNames: [ "TimeInstant" ], creDate: 1510662361, modDate: 1510664113 }, attrs.TimeInstant:

      { value: "2017-11-14T12:55:13.800Z", type: "ISO8601", mdNames: [], creDate: 1510662361, modDate: 1510664113 }

      , modDate: 1510664113, lastCorrelator: "0e4a4e20-c93b-11e7-957f-0242ac110003" }, $unset:

      { location: 1 }

      }>)
      time=Tuesday 14 Nov 12:55:13 2017.812Z | lvl=INFO | corr=0e4a4e20-c93b-11e7-957f-0242ac110003 | trans=1510663280-019-00000000012 | from=54.194.53.34 | srv=howtoservice | subsrv=/howto | comp=Orion | op=logMsg.h[1916]:lmTransactionEnd | msg=Transaction ended
      time=Tuesday 14 Nov 12:55:13 2017.812Z | lvl=INFO | corr=N/A | trans=1510663280-019-00000000013 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=logMsg.h[1832]:lmTransactionStart | msg=Starting transaction to https://iot.visualfy.com:443/api/v1/devices/orion/local
      time=Tuesday 14 Nov 12:55:13 2017.812Z | lvl=INFO | corr=N/A | trans=1510663280-019-00000000013 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=httpRequestSend.cpp[599]:httpRequestSendWithCurl | msg=Sending message 3 to HTTP server: sending message of 535 bytes to HTTP server
      time=Tuesday 14 Nov 12:55:13 2017.891Z | lvl=INFO | corr=N/A | trans=1510663280-019-00000000013 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=logMsg.h[1916]:lmTransactionEnd | msg=Transaction ended

      The subscription is the same with the http attribute changed to the endpoint.

      Any help would be appreciated and if you need further information don't hesitate asking.

      UPDATE 1

      After shutting down the process in the 443 port and adding a listener, performing a netcat like: nc -l 443 has resulted in a notification arriving to netcat with a non readable data stream.
      The orion context broker logs shows some interesting information:

      time=Friday 17 Nov 11:05:56 2017.587Z | lvl=INFO | corr=N/A | trans=1510663280-019-00000000090 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=logMsg.h[1832]:lmTransactionStart | msg=Starting transaction to https://34.240.0.113:443/api/v1/devices/orion/local
      time=Friday 17 Nov 11:05:56 2017.587Z | lvl=INFO | corr=N/A | trans=1510663280-019-00000000090 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=httpRequestSend.cpp[599]:httpRequestSendWithCurl | msg=Sending message 22 to HTTP server: sending message of 531 bytes to HTTP server
      time=Friday 17 Nov 11:06:04 2017.153Z | lvl=INFO | corr=4da159ee-cb87-11e7-97f4-0242ac110003 | trans=1510663280-019-00000000091 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=logMsg.h[1832]:lmTransactionStart | msg=Starting transaction from 37.11.95.120:60933/v2/subscriptions
      time=Friday 17 Nov 11:06:04 2017.154Z | lvl=INFO | corr=4da159ee-cb87-11e7-97f4-0242ac110003 | trans=1510663280-019-00000000091 | from=37.11.95.120 | srv=pending | subsrv=/howto | comp=Orion | op=rest.cpp[882]:servicePathSplit | msg=Service Path 0: '/howto'
      time=Friday 17 Nov 11:06:04 2017.154Z | lvl=INFO | corr=4da159ee-cb87-11e7-97f4-0242ac110003 | trans=1510663280-019-00000000091 | from=37.11.95.120 | srv=howtoservice | subsrv=/howto | comp=Orion | op=connectionOperations.cpp[175]:collectionRangedQuery | msg=Database Operation Successful (query: { query:

      { servicePath: "/howto" }

      , orderby:

      { _id: 1 }

      })
      time=Friday 17 Nov 11:06:04 2017.155Z | lvl=INFO | corr=4da159ee-cb87-11e7-97f4-0242ac110003 | trans=1510663280-019-00000000091 | from=37.11.95.120 | srv=howtoservice | subsrv=/howto | comp=Orion | op=logMsg.h[1916]:lmTransactionEnd | msg=Transaction ended
      time=Friday 17 Nov 11:06:04 2017.556Z | lvl=WARN | corr=N/A | trans=1510663280-019-00000000090 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=AlarmManager.cpp[328]:notificationError | msg=Raising alarm NotificationError https://34.240.0.113:443/api/v1/devices/orion/local: (curl_easy_perform failed: SSL connect error)

      Which has the same looking than the failed notification instead of the one that ended OK.

      The same process to the service that is working, when the notification reachs netcat has more characters notifying. In other words, this is what I receive in the netcat that doesnt receive notifications correctly:

      HD?#

      ??s???s0?^0M
      c1\6?QSb?J3298/5
      ?

      And this is what I receive in the netcat that receive the notifications OK:

      ?_??=?)>B??w{?d?O?އ?$V? ?bG??B?>?????
      ??O?[06?gZZ̨̩?+?/?,?0????/5
      ? ?&?ualfy.secmotic.com#?ۻ??f??s??? ir??b?;?!~?"-$?}?G?A?Ӎ8??ؽV?%2ߨ??B&?
      ?Wr?n?<=T?h?A{R?Ϛ?y??'L1??1????w"m?kY?oKl??5%'?["?X9??h?f?`?Hj?%mZ?{?I?ʤx??v???m??H?9?????Ƥf%
      hhttp/1.1uP

      ????@^C

      UPDATE 2
      It is clear now that it is an HTTPS error with the notifications.
      I have gone in the docker container where Orion Context Broker is and tried to perform a curl to the HTTPS domain, having the following output:

      • About to connect() to iot.visualfy.com port 443 (#0)
      • Trying 34.240.0.113... connected
      • Connected to iot.visualfy.com (34.240.0.113) port 443 (#0)
      • Initializing NSS with certpath: sql:/etc/pki/nssdb
      • CAfile: /etc/pki/tls/certs/ca-bundle.crt
        CApath: none
      • NSS error -5961
      • Closing connection #0
      • SSL connect error
        curl: (35) SSL connect error

      I actually tried to configure Orion as the documentation says with the -insecureNotif option, but the result is the same.

        Activity

        Hide
        backlogmanager Backlog Manager added a comment -

        2018-01-12 19:50|CREATED monitor | # answers= 1, accepted answer= True

        Show
        backlogmanager Backlog Manager added a comment - 2018-01-12 19:50|CREATED monitor | # answers= 1, accepted answer= True
        Hide
        backlogmanager Backlog Manager added a comment -

        2018-01-12 19:53|UPDATED status: transition Answer| # answers= 1, accepted answer= True

        Show
        backlogmanager Backlog Manager added a comment - 2018-01-12 19:53|UPDATED status: transition Answer| # answers= 1, accepted answer= True
        Hide
        backlogmanager Backlog Manager added a comment -

        2018-01-12 20:02|UPDATED status: transition Finish| # answers= 1, accepted answer= True

        Show
        backlogmanager Backlog Manager added a comment - 2018-01-12 20:02|UPDATED status: transition Finish| # answers= 1, accepted answer= True

          People

          • Assignee:
            backlogmanager Backlog Manager
            Reporter:
            backlogmanager Backlog Manager
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: