search

telefonicaid / fiware-cygnus

A connector in charge of persisting context data sources into other third-party databases and storage systems, creating a historical view of the context
https://fiware-cygnus.rtfd.io/
GNU Affero General Public License v3.0
65 stars 105 forks source link

Cygnus-CKAN, does not process correctly the compound notifications #102

Closed iariasleon closed 10 years ago

iariasleon commented 10 years ago

Severity: Major (6) - BUG Cygnus version used: cygnus-0.4_SNAPSHOT-14.gd553b14.x86_64.rpm Log mode: DEBUG Script executed: notification-xml-compound.sh 127.0.0.1:5050/notify org58

When we process a compound notification, ex:

<notifyContextRequest>
  <subscriptionId>51c0ac9ed714fb3b37d7d5a8</subscriptionId>
  <originator>localhost</originator>
  <contextResponseList>
    <contextElementResponse>
      <contextElement>
        <entityId type="Room" isPattern="false">
          <id>Room3</id>
        </entityId>
        <contextAttributeList>
          <contextAttribute>
            <name>field1</name>
            <type>type1</type>
            <contextValue>
              <a>1</a>
              <b>2</b>
            </contextValue>
          </contextAttribute>
          <contextAttribute>
            <name>field2</name>
            <type>type2</type>
            <contextValue type="vector">
              <item>v1</item>
              <item>v2</item>
            </contextValue>
          </contextAttribute>
        </contextAttributeList>
      </contextElement>
      <statusCode>
        <code>200</code>
        <reasonPhrase>OK</reasonPhrase>
      </statusCode>
    </contextElementResponse>
  </contextResponseList>
</notifyContextRequest>

Cygnus does not process this notification, showing this error indefinitely:

23 Jul 2014 16:09:15,170 INFO  [SinkRunner-PollingRunner-DefaultSinkProcessor] (es.tid.fiware.fiwareconnectors.cygnus.sinks.OrionSink.process:98)  - An event was taken from the channel, it must be persisted
23 Jul 2014 16:09:15,170 INFO  [SinkRunner-PollingRunner-DefaultSinkProcessor] (es.tid.fiware.fiwareconnectors.cygnus.sinks.OrionSink.process:98)  - An event was taken from the channel, it must be persisted
23 Jul 2014 16:09:15,171 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (es.tid.fiware.fiwareconnectors.cygnus.sinks.OrionSink.persist:140)  - The content-type was application/xml
23 Jul 2014 16:09:15,171 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (es.tid.fiware.fiwareconnectors.cygnus.sinks.OrionSink.persist:140)  - The content-type was application/xml
23 Jul 2014 16:09:15,174 INFO  [SinkRunner-PollingRunner-DefaultSinkProcessor] (es.tid.fiware.fiwareconnectors.cygnus.backends.ckan.CKANBackendImpl.initOrg:94)  - organization org58 already initialized
23 Jul 2014 16:09:15,174 INFO  [SinkRunner-PollingRunner-DefaultSinkProcessor] (es.tid.fiware.fiwareconnectors.cygnus.backends.ckan.CKANBackendImpl.initOrg:94)  - organization org58 already initialized
23 Jul 2014 16:09:15,175 INFO  [SinkRunner-PollingRunner-DefaultSinkProcessor] (es.tid.fiware.fiwareconnectors.cygnus.sinks.OrionCKANSink.persist:191)  - Persisting data: <1406124528656, 2014-07-23T16:08:48.656, org58, Room3-Room, field1, type1, {"a":"1","b":"2"}, []>
23 Jul 2014 16:09:15,175 INFO  [SinkRunner-PollingRunner-DefaultSinkProcessor] (es.tid.fiware.fiwareconnectors.cygnus.sinks.OrionCKANSink.persist:191)  - Persisting data: <1406124528656, 2014-07-23T16:08:48.656, org58, Room3-Room, field1, type1, {"a":"1","b":"2"}, []>
23 Jul 2014 16:09:15,175 INFO  [SinkRunner-PollingRunner-DefaultSinkProcessor] (es.tid.fiware.fiwareconnectors.cygnus.backends.ckan.CKANBackendImpl.resourceLookupAndCreate:186)  - lookup in resources map <org58,Room3-Room>
23 Jul 2014 16:09:15,175 INFO  [SinkRunner-PollingRunner-DefaultSinkProcessor] (es.tid.fiware.fiwareconnectors.cygnus.backends.ckan.CKANBackendImpl.resourceLookupAndCreate:186)  - lookup in resources map <org58,Room3-Room>
23 Jul 2014 16:09:15,175 INFO  [SinkRunner-PollingRunner-DefaultSinkProcessor] (es.tid.fiware.fiwareconnectors.cygnus.backends.ckan.CKANBackendImpl.resourceLookupAndCreate:191)  - resolved <org58,Room3-Room> -> eaa1f75b-776e-459a-b06c-60205701b892
23 Jul 2014 16:09:15,175 INFO  [SinkRunner-PollingRunner-DefaultSinkProcessor] (es.tid.fiware.fiwareconnectors.cygnus.backends.ckan.CKANBackendImpl.resourceLookupAndCreate:191)  - resolved <org58,Room3-Room> -> eaa1f75b-776e-459a-b06c-60205701b892
23 Jul 2014 16:09:15,175 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (es.tid.fiware.fiwareconnectors.cygnus.backends.ckan.CKANBackendImpl.doCKANRequest:481)  - request payload: { "resource_id": "eaa1f75b-776e-459a-b06c-60205701b892", "records": [ { "recvTimeTs": "1406124528", "recvTime": "2014-07-23T16:08:48.656", "attrName": "field1", "attrType": "type1", "attrValue": "{"a":"1","b":"2"}" } ], "method": "insert", "force": "true" }
23 Jul 2014 16:09:15,175 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (es.tid.fiware.fiwareconnectors.cygnus.backends.ckan.CKANBackendImpl.doCKANRequest:481)  - request payload: { "resource_id": "eaa1f75b-776e-459a-b06c-60205701b892", "records": [ { "recvTimeTs": "1406124528", "recvTime": "2014-07-23T16:08:48.656", "attrName": "field1", "attrType": "type1", "attrValue": "{"a":"1","b":"2"}" } ], "method": "insert", "force": "true" }
23 Jul 2014 16:09:15,176 INFO  [SinkRunner-PollingRunner-DefaultSinkProcessor] (es.tid.fiware.fiwareconnectors.cygnus.backends.ckan.CKANBackendImpl.doCKANRequest:493)  - CKAN operation: POST http://130.206.83.8:80/api/3/action/datastore_upsert HTTP/1.1
23 Jul 2014 16:09:15,176 INFO  [SinkRunner-PollingRunner-DefaultSinkProcessor] (es.tid.fiware.fiwareconnectors.cygnus.backends.ckan.CKANBackendImpl.doCKANRequest:493)  - CKAN operation: POST http://130.206.83.8:80/api/3/action/datastore_upsert HTTP/1.1
23 Jul 2014 16:09:15,176 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.PoolingClientConnectionManager.requestConnection:186)  - Connection request: [route: {}->http://130.206.83.8:80][total kept alive: 1; route allocated: 1 of 100; total allocated: 1 of 500]
23 Jul 2014 16:09:15,176 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.PoolingClientConnectionManager.requestConnection:186)  - Connection request: [route: {}->http://130.206.83.8:80][total kept alive: 1; route allocated: 1 of 100; total allocated: 1 of 500]
23 Jul 2014 16:09:15,177 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.PoolingClientConnectionManager.leaseConnection:220)  - Connection leased: [id: 0][route: {}->http://130.206.83.8:80][total kept alive: 0; route allocated: 1 of 100; total allocated: 1 of 500]
23 Jul 2014 16:09:15,177 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.PoolingClientConnectionManager.leaseConnection:220)  - Connection leased: [id: 0][route: {}->http://130.206.83.8:80][total kept alive: 0; route allocated: 1 of 100; total allocated: 1 of 500]
23 Jul 2014 16:09:15,177 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.client.DefaultRequestDirector.execute:465)  - Stale connection check
23 Jul 2014 16:09:15,177 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.client.DefaultRequestDirector.execute:465)  - Stale connection check
23 Jul 2014 16:09:15,178 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.client.protocol.RequestAddCookies.process:132)  - CookieSpec selected: best-match
23 Jul 2014 16:09:15,178 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.client.protocol.RequestAddCookies.process:132)  - CookieSpec selected: best-match
23 Jul 2014 16:09:15,179 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.client.protocol.RequestAuthCache.process:78)  - Auth cache not set in the context
23 Jul 2014 16:09:15,179 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.client.protocol.RequestAuthCache.process:78)  - Auth cache not set in the context
23 Jul 2014 16:09:15,179 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.client.protocol.RequestProxyAuthentication.process:87)  - Proxy auth state: UNCHALLENGED
23 Jul 2014 16:09:15,179 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.client.protocol.RequestProxyAuthentication.process:87)  - Proxy auth state: UNCHALLENGED
23 Jul 2014 16:09:15,179 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.client.DefaultRequestDirector.tryExecute:710)  - Attempt 1 to execute request
23 Jul 2014 16:09:15,179 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.client.DefaultRequestDirector.tryExecute:710)  - Attempt 1 to execute request
23 Jul 2014 16:09:15,179 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader:269)  - Sending request: POST /api/3/action/datastore_upsert HTTP/1.1
23 Jul 2014 16:09:15,179 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader:269)  - Sending request: POST /api/3/action/datastore_upsert HTTP/1.1
23 Jul 2014 16:09:15,180 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - >> "POST /api/3/action/datastore_upsert HTTP/1.1[\r][\n]"
23 Jul 2014 16:09:15,180 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - >> "POST /api/3/action/datastore_upsert HTTP/1.1[\r][\n]"
23 Jul 2014 16:09:15,180 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - >> "Authorization: f3627131-8184-42e7-ab33-9bf0f7e22dff[\r][\n]"
23 Jul 2014 16:09:15,180 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - >> "Authorization: f3627131-8184-42e7-ab33-9bf0f7e22dff[\r][\n]"
23 Jul 2014 16:09:15,180 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - >> "Content-Length: 257[\r][\n]"
23 Jul 2014 16:09:15,180 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - >> "Content-Length: 257[\r][\n]"
23 Jul 2014 16:09:15,180 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - >> "Content-Type: application/json[\r][\n]"
23 Jul 2014 16:09:15,180 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - >> "Content-Type: application/json[\r][\n]"
23 Jul 2014 16:09:15,180 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - >> "Host: 130.206.83.8:80[\r][\n]"
23 Jul 2014 16:09:15,180 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - >> "Host: 130.206.83.8:80[\r][\n]"
23 Jul 2014 16:09:15,181 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - >> "Connection: Keep-Alive[\r][\n]"
23 Jul 2014 16:09:15,181 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - >> "Connection: Keep-Alive[\r][\n]"
23 Jul 2014 16:09:15,181 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - >> "User-Agent: Apache-HttpClient/4.2.1 (java 1.5)[\r][\n]"
23 Jul 2014 16:09:15,181 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - >> "User-Agent: Apache-HttpClient/4.2.1 (java 1.5)[\r][\n]"
23 Jul 2014 16:09:15,181 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - >> "[\r][\n]"
23 Jul 2014 16:09:15,181 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - >> "[\r][\n]"
23 Jul 2014 16:09:15,181 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader:273)  - >> POST /api/3/action/datastore_upsert HTTP/1.1
23 Jul 2014 16:09:15,181 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader:273)  - >> POST /api/3/action/datastore_upsert HTTP/1.1
23 Jul 2014 16:09:15,182 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader:276)  - >> Authorization: f3627131-8184-42e7-ab33-9bf0f7e22dff
23 Jul 2014 16:09:15,182 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader:276)  - >> Authorization: f3627131-8184-42e7-ab33-9bf0f7e22dff
23 Jul 2014 16:09:15,182 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader:276)  - >> Content-Length: 257
23 Jul 2014 16:09:15,182 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader:276)  - >> Content-Length: 257
23 Jul 2014 16:09:15,182 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader:276)  - >> Content-Type: application/json
23 Jul 2014 16:09:15,182 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader:276)  - >> Content-Type: application/json
23 Jul 2014 16:09:15,182 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader:276)  - >> Host: 130.206.83.8:80
23 Jul 2014 16:09:15,182 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader:276)  - >> Host: 130.206.83.8:80
23 Jul 2014 16:09:15,183 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader:276)  - >> Connection: Keep-Alive
23 Jul 2014 16:09:15,183 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader:276)  - >> Connection: Keep-Alive
23 Jul 2014 16:09:15,183 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader:276)  - >> User-Agent: Apache-HttpClient/4.2.1 (java 1.5)
23 Jul 2014 16:09:15,183 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader:276)  - >> User-Agent: Apache-HttpClient/4.2.1 (java 1.5)
23 Jul 2014 16:09:15,183 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:77)  - >> "{ "resource_id": "eaa1f75b-776e-459a-b06c-60205701b892", "records": [ { "recvTimeTs": "1406124528", "recvTime": "2014-07-23T16:08:48.656", "attrName": "field1", "attrType": "type1", "attrValue": "{"a":"1","b":"2"}" } ], "method": "insert", "force": "true" }"
23 Jul 2014 16:09:15,183 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:77)  - >> "{ "resource_id": "eaa1f75b-776e-459a-b06c-60205701b892", "records": [ { "recvTimeTs": "1406124528", "recvTime": "2014-07-23T16:08:48.656", "attrName": "field1", "attrType": "type1", "attrValue": "{"a":"1","b":"2"}" } ], "method": "insert", "force": "true" }"
23 Jul 2014 16:09:15,305 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "HTTP/1.1 400 Bad Request[\r][\n]"
23 Jul 2014 16:09:15,305 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "HTTP/1.1 400 Bad Request[\r][\n]"
23 Jul 2014 16:09:15,306 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "Server: PasteWSGIServer/0.5 Python/2.7.4[\r][\n]"
23 Jul 2014 16:09:15,306 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "Server: PasteWSGIServer/0.5 Python/2.7.4[\r][\n]"
23 Jul 2014 16:09:15,306 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "Date: Wed, 23 Jul 2014 14:09:15 GMT[\r][\n]"
23 Jul 2014 16:09:15,306 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "Date: Wed, 23 Jul 2014 14:09:15 GMT[\r][\n]"
23 Jul 2014 16:09:15,306 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "Pragma: no-cache[\r][\n]"
23 Jul 2014 16:09:15,306 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "Pragma: no-cache[\r][\n]"
23 Jul 2014 16:09:15,306 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "Content-Type: application/json;charset=utf-8[\r][\n]"
23 Jul 2014 16:09:15,306 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "Content-Type: application/json;charset=utf-8[\r][\n]"
23 Jul 2014 16:09:15,307 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "Content-Length: 483[\r][\n]"
23 Jul 2014 16:09:15,307 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "Content-Length: 483[\r][\n]"
23 Jul 2014 16:09:15,307 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "Access-Control-Allow-Origin: *[\r][\n]"
23 Jul 2014 16:09:15,307 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "Access-Control-Allow-Origin: *[\r][\n]"
23 Jul 2014 16:09:15,307 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "Access-Control-Allow-Methods: POST, PUT, GET, DELETE, OPTIONS[\r][\n]"
23 Jul 2014 16:09:15,307 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "Access-Control-Allow-Methods: POST, PUT, GET, DELETE, OPTIONS[\r][\n]"
23 Jul 2014 16:09:15,307 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "Access-Control-Allow-Headers: X-CKAN-API-KEY, Authorization, Content-Type[\r][\n]"
23 Jul 2014 16:09:15,307 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "Access-Control-Allow-Headers: X-CKAN-API-KEY, Authorization, Content-Type[\r][\n]"
23 Jul 2014 16:09:15,308 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "Cache-Control: no-cache, proxy-revalidate[\r][\n]"
23 Jul 2014 16:09:15,308 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "Cache-Control: no-cache, proxy-revalidate[\r][\n]"
23 Jul 2014 16:09:15,308 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "Connection: Keep-Alive[\r][\n]"
23 Jul 2014 16:09:15,308 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "Connection: Keep-Alive[\r][\n]"
23 Jul 2014 16:09:15,308 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "Age: 0[\r][\n]"
23 Jul 2014 16:09:15,308 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "Age: 0[\r][\n]"
23 Jul 2014 16:09:15,308 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "[\r][\n]"
23 Jul 2014 16:09:15,308 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:63)  - << "[\r][\n]"
23 Jul 2014 16:09:15,309 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:254)  - Receiving response: HTTP/1.1 400 Bad Request
23 Jul 2014 16:09:15,309 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:254)  - Receiving response: HTTP/1.1 400 Bad Request
23 Jul 2014 16:09:15,309 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:257)  - << HTTP/1.1 400 Bad Request
23 Jul 2014 16:09:15,309 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:257)  - << HTTP/1.1 400 Bad Request
23 Jul 2014 16:09:15,309 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:260)  - << Server: PasteWSGIServer/0.5 Python/2.7.4
23 Jul 2014 16:09:15,309 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:260)  - << Server: PasteWSGIServer/0.5 Python/2.7.4
23 Jul 2014 16:09:15,309 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:260)  - << Date: Wed, 23 Jul 2014 14:09:15 GMT
23 Jul 2014 16:09:15,309 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:260)  - << Date: Wed, 23 Jul 2014 14:09:15 GMT
23 Jul 2014 16:09:15,309 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:260)  - << Pragma: no-cache
23 Jul 2014 16:09:15,309 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:260)  - << Pragma: no-cache
23 Jul 2014 16:09:15,310 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:260)  - << Content-Type: application/json;charset=utf-8
23 Jul 2014 16:09:15,310 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:260)  - << Content-Type: application/json;charset=utf-8
23 Jul 2014 16:09:15,310 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:260)  - << Content-Length: 483
23 Jul 2014 16:09:15,310 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:260)  - << Content-Length: 483
23 Jul 2014 16:09:15,310 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:260)  - << Access-Control-Allow-Origin: *
23 Jul 2014 16:09:15,310 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:260)  - << Access-Control-Allow-Origin: *
23 Jul 2014 16:09:15,310 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:260)  - << Access-Control-Allow-Methods: POST, PUT, GET, DELETE, OPTIONS
23 Jul 2014 16:09:15,310 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:260)  - << Access-Control-Allow-Methods: POST, PUT, GET, DELETE, OPTIONS
23 Jul 2014 16:09:15,310 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:260)  - << Access-Control-Allow-Headers: X-CKAN-API-KEY, Authorization, Content-Type
23 Jul 2014 16:09:15,310 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:260)  - << Access-Control-Allow-Headers: X-CKAN-API-KEY, Authorization, Content-Type
23 Jul 2014 16:09:15,311 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:260)  - << Cache-Control: no-cache, proxy-revalidate
23 Jul 2014 16:09:15,311 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:260)  - << Cache-Control: no-cache, proxy-revalidate
23 Jul 2014 16:09:15,311 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:260)  - << Connection: Keep-Alive
23 Jul 2014 16:09:15,311 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:260)  - << Connection: Keep-Alive
23 Jul 2014 16:09:15,311 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:260)  - << Age: 0
23 Jul 2014 16:09:15,311 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader:260)  - << Age: 0
23 Jul 2014 16:09:15,311 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.client.DefaultRequestDirector.execute:540)  - Connection can be kept alive indefinitely
23 Jul 2014 16:09:15,311 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.client.DefaultRequestDirector.execute:540)  - Connection can be kept alive indefinitely
23 Jul 2014 16:09:15,312 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:77)  - << ""Bad request - JSON Error: Error decoding JSON data. Error: JSONDecodeError(\"Expecting ',' delimiter or '}': line 1 column 199 (char 198)\",) JSON data extracted from the request: '{ \"resource_id\": \"eaa1f75b-776e-459a-b06c-60205701b892\", \"records\": [ { \"recvTimeTs\": \"1406124528\", \"recvTime\": \"2014-07-23T16:08:48.656\", \"attrName\": \"field1\", \"attrType\": \"type1\", \"attrValue\": \"{\"a\":\"1\",\"b\":\"2\"}\" } ], \"method\": \"insert\", \"force\": \"true\" }'""
23 Jul 2014 16:09:15,312 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.Wire.wire:77)  - << ""Bad request - JSON Error: Error decoding JSON data. Error: JSONDecodeError(\"Expecting ',' delimiter or '}': line 1 column 199 (char 198)\",) JSON data extracted from the request: '{ \"resource_id\": \"eaa1f75b-776e-459a-b06c-60205701b892\", \"records\": [ { \"recvTimeTs\": \"1406124528\", \"recvTime\": \"2014-07-23T16:08:48.656\", \"attrName\": \"field1\", \"attrType\": \"type1\", \"attrValue\": \"{\"a\":\"1\",\"b\":\"2\"}\" } ], \"method\": \"insert\", \"force\": \"true\" }'""
23 Jul 2014 16:09:15,312 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.PoolingClientConnectionManager.releaseConnection:272)  - Connection [id: 0][route: {}->http://130.206.83.8:80] can be kept alive indefinitely
23 Jul 2014 16:09:15,312 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.PoolingClientConnectionManager.releaseConnection:272)  - Connection [id: 0][route: {}->http://130.206.83.8:80] can be kept alive indefinitely
23 Jul 2014 16:09:15,312 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.PoolingClientConnectionManager.releaseConnection:278)  - Connection released: [id: 0][route: {}->http://130.206.83.8:80][total kept alive: 1; route allocated: 1 of 100; total allocated: 1 of 500]
23 Jul 2014 16:09:15,312 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (org.apache.http.impl.conn.PoolingClientConnectionManager.releaseConnection:278)  - Connection released: [id: 0][route: {}->http://130.206.83.8:80][total kept alive: 1; route allocated: 1 of 100; total allocated: 1 of 500]
23 Jul 2014 16:09:15,312 INFO  [SinkRunner-PollingRunner-DefaultSinkProcessor] (es.tid.fiware.fiwareconnectors.cygnus.backends.ckan.CKANBackendImpl.doCKANRequest:499)  - CKAN response (483 bytes): HTTP/1.1 400 Bad Request
23 Jul 2014 16:09:15,312 INFO  [SinkRunner-PollingRunner-DefaultSinkProcessor] (es.tid.fiware.fiwareconnectors.cygnus.backends.ckan.CKANBackendImpl.doCKANRequest:499)  - CKAN response (483 bytes): HTTP/1.1 400 Bad Request
23 Jul 2014 16:09:15,312 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (es.tid.fiware.fiwareconnectors.cygnus.backends.ckan.CKANBackendImpl.doCKANRequest:502)  - response payload: "Bad request - JSON Error: Error decoding JSON data. Error: JSONDecodeError(\"Expecting ',' delimiter or '}': line 1 column 199 (char 198)\",) JSON data extracted from the request: '{ \"resource_id\": \"eaa1f75b-776e-459a-b06c-60205701b892\", \"records\": [ { \"recvTimeTs\": \"1406124528\", \"recvTime\": \"2014-07-23T16:08:48.656\", \"attrName\": \"field1\", \"attrType\": \"type1\", \"attrValue\": \"{\"a\":\"1\",\"b\":\"2\"}\" } ], \"method\": \"insert\", \"force\": \"true\" }'"
23 Jul 2014 16:09:15,312 DEBUG [SinkRunner-PollingRunner-DefaultSinkProcessor] (es.tid.fiware.fiwareconnectors.cygnus.backends.ckan.CKANBackendImpl.doCKANRequest:502)  - response payload: "Bad request - JSON Error: Error decoding JSON data. Error: JSONDecodeError(\"Expecting ',' delimiter or '}': line 1 column 199 (char 198)\",) JSON data extracted from the request: '{ \"resource_id\": \"eaa1f75b-776e-459a-b06c-60205701b892\", \"records\": [ { \"recvTimeTs\": \"1406124528\", \"recvTime\": \"2014-07-23T16:08:48.656\", \"attrName\": \"field1\", \"attrType\": \"type1\", \"attrValue\": \"{\"a\":\"1\",\"b\":\"2\"}\" } ], \"method\": \"insert\", \"force\": \"true\" }'"
23 Jul 2014 16:09:15,313 ERROR [SinkRunner-PollingRunner-DefaultSinkProcessor] (es.tid.fiware.fiwareconnectors.cygnus.sinks.OrionSink.process:106)  - java.lang.String cannot be cast to org.json.simple.JSONObject
23 Jul 2014 16:09:15,313 ERROR [SinkRunner-PollingRunner-DefaultSinkProcessor] (es.tid.fiware.fiwareconnectors.cygnus.sinks.OrionSink.process:106)  - java.lang.String cannot be cast to org.json.simple.JSONObject
fgalan commented 10 years ago

Having the full log is fine to have all the information. However, it would be great if we can also know the section in which the bug manisfest. E.g. the JSON string that is causing the problem (usually a "wire" debug arround the 404 error).

frbattid commented 10 years ago

Just for clarification, the error loop is due to the main reliability mechanism given by Flume, based on re-injecting an event in the channel if it could not be processed. Nevertheless, we are currently abusing of such mechanism, since we re-inject all the not processed events, even those that are malformed and will never be processed althought they are re-injected forever :)

There is an issue regarding this: https://github.com/telefonicaid/fiware-connectors/issues/52

fgalan commented 10 years ago

I think this should be fixed in PR #97. Let's merge that PR into develop, then evaluate if the bug still happening again.

fgalan commented 10 years ago

It could be related with issue #106

iariasleon commented 10 years ago

LGTM