search

odalic / sti

An API and enhancements to the Semantic Table Interpretation
Other
3 stars 0 forks source link

Logging: When task fails there is no info why does it fail #210

Closed tomas-knap closed 7 years ago

tomas-knap commented 7 years ago

I define new task, run it. Then, when observing logs in tomcat (catalina.out), I got the log as below. But from that, I do not know where the problem was. So ideally the service returning status of the execution should provide some more detail if there is an error state. Could be something low level (like the exception) to start with, so that consumer of such service can see what happened.

Btw. the log of the Odalic Core execution disappeared from the consol (catalina.out), that was on purpose?

.15:27:25.059 [http-nio-8080-exec-19] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path files 
.15:27:25.064 [http-nio-8080-exec-19] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : [ {
    "id" : "Books-v1.csv",
    "uploaded" : 1479392190176,
    "owner" : "",
    "location" : "http://localhost:8080/odalic/files/Books-v1.csv",
    "cached" : true
  } ]
} 
.15:27:40.874 [http-nio-8080-exec-15] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting OPTIONS for path tasks/b 
.15:27:40.874 [http-nio-8080-exec-15] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply "PD94bWwgdmVyc2lvbj0iMS4wIiBlbmNvZGluZz0iVVRGLTgiIHN0YW5kYWxvbmU9InllcyI/Pgo8YXBwbGljYXRpb24geG1sbnM9Imh0dHA6Ly93YWRsLmRldi5qYXZhLm5ldC8yMDA5LzAyIj4KICAgIDxkb2MgeG1sbnM6amVyc2V5PSJodHRwOi8vamVyc2V5LmphdmEubmV0LyIgamVyc2V5OmdlbmVyYXRlZEJ5PSJKZXJzZXk6IDIuMjMuMSAyMDE2LTA2LTA5IDE4OjA1OjQ3Ii8+CiAgICA8Z3JhbW1hcnM+CiAgICAgICAgPGluY2x1ZGUgaHJlZj0iaHR0cDovL2xvY2FsaG9zdDo4MDgwL29kYWxpYy9hcHBsaWNhdGlvbi53YWRsL3hzZDAueHNkIj4KICAgICAgICAgICAgPGRvYyB0aXRsZT0iR2VuZXJhdGVkIiB4bWw6bGFuZz0iZW4iLz4KICAgICAgICA8L2luY2x1ZGU+CiAgICA8L2dyYW1tYXJzPgogICAgPHJlc291cmNlcyBiYXNlPSJodHRwOi8vbG9jYWxob3N0OjgwODAvb2RhbGljLyI+CiAgICAgICAgPHJlc291cmNlIHBhdGg9InRhc2tzL2IiPgogICAgICAgICAgICA8bWV0aG9kIGlkPSJnZXRUYXNrQnlJZCIgbmFtZT0iR0VUIj4KICAgICAgICAgICAgICAgIDxyZXNwb25zZT4KICAgICAgICAgICAgICAgICAgICA8cmVwcmVzZW50YXRpb24gbWVkaWFUeXBlPSJhcHBsaWNhdGlvbi9qc29uIi8+CiAgICAgICAgICAgICAgICA8L3Jlc3BvbnNlPgogICAgICAgICAgICA8L21ldGhvZD4KICAgICAgICAgICAgPG1ldGhvZCBpZD0icHV0VGFza1dpdGhJZCIgbmFtZT0iUFVUIj4KICAgICAgICAgICAgICAgIDxyZXF1ZXN0PgogICAgICAgICAgICAgICAgICAgIDxuczI6cmVwcmVzZW50YXRpb24geG1sbnM6bnMyPSJodHRwOi8vd2FkbC5kZXYuamF2YS5uZXQvMjAwOS8wMiIgeG1sbnM9IiIgZWxlbWVudD0idGFzayIgbWVkaWFUeXBlPSJhcHBsaWNhdGlvbi9qc29uIi8+CiAgICAgICAgICAgICAgICA8L3JlcXVlc3Q+CiAgICAgICAgICAgICAgICA8cmVzcG9uc2U+CiAgICAgICAgICAgICAgICAgICAgPHJlcHJlc2VudGF0aW9uIG1lZGlhVHlwZT0iYXBwbGljYXRpb24vanNvbiIvPgogICAgICAgICAgICAgICAgPC9yZXNwb25zZT4KICAgICAgICAgICAgPC9tZXRob2Q+CiAgICAgICAgICAgIDxtZXRob2QgaWQ9ImRlbGV0ZVRhc2tCeUlkIiBuYW1lPSJERUxFVEUiPgogICAgICAgICAgICAgICAgPHJlc3BvbnNlPgogICAgICAgICAgICAgICAgICAgIDxyZXByZXNlbnRhdGlvbiBtZWRpYVR5cGU9ImFwcGxpY2F0aW9uL2pzb24iLz4KICAgICAgICAgICAgICAgIDwvcmVzcG9uc2U+CiAgICAgICAgICAgIDwvbWV0aG9kPgogICAgICAgIDwvcmVzb3VyY2U+CiAgICA8L3Jlc291cmNlcz4KPC9hcHBsaWNhdGlvbj4K" 
.15:27:40.888 [http-nio-8080-exec-12] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting PUT for path tasks/b 
.15:27:40.891 [http-nio-8080-exec-12] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 201,
  "type" : "MESSAGE",
  "payload" : {
    "text" : "A new task has been created AT THE LOCATION you specified",
    "additionalResources" : [ ],
    "debugContent" : null
  }
} 
.15:27:40.979 [http-nio-8080-exec-10] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting OPTIONS for path tasks/b/execution 
.15:27:40.979 [http-nio-8080-exec-10] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply "PD94bWwgdmVyc2lvbj0iMS4wIiBlbmNvZGluZz0iVVRGLTgiIHN0YW5kYWxvbmU9InllcyI/Pgo8YXBwbGljYXRpb24geG1sbnM9Imh0dHA6Ly93YWRsLmRldi5qYXZhLm5ldC8yMDA5LzAyIj4KICAgIDxkb2MgeG1sbnM6amVyc2V5PSJodHRwOi8vamVyc2V5LmphdmEubmV0LyIgamVyc2V5OmdlbmVyYXRlZEJ5PSJKZXJzZXk6IDIuMjMuMSAyMDE2LTA2LTA5IDE4OjA1OjQ3Ii8+CiAgICA8Z3JhbW1hcnM+CiAgICAgICAgPGluY2x1ZGUgaHJlZj0iaHR0cDovL2xvY2FsaG9zdDo4MDgwL29kYWxpYy9hcHBsaWNhdGlvbi53YWRsL3hzZDAueHNkIj4KICAgICAgICAgICAgPGRvYyB0aXRsZT0iR2VuZXJhdGVkIiB4bWw6bGFuZz0iZW4iLz4KICAgICAgICA8L2luY2x1ZGU+CiAgICA8L2dyYW1tYXJzPgogICAgPHJlc291cmNlcyBiYXNlPSJodHRwOi8vbG9jYWxob3N0OjgwODAvb2RhbGljLyI+CiAgICAgICAgPHJlc291cmNlIHBhdGg9InRhc2tzL2IvZXhlY3V0aW9uIj4KICAgICAgICAgICAgPG1ldGhvZCBpZD0icHV0RXhlY3V0aW9uRm9yVGFza0lkIiBuYW1lPSJQVVQiPgogICAgICAgICAgICAgICAgPHJlcXVlc3Q+CiAgICAgICAgICAgICAgICAgICAgPG5zMjpyZXByZXNlbnRhdGlvbiB4bWxuczpuczI9Imh0dHA6Ly93YWRsLmRldi5qYXZhLm5ldC8yMDA5LzAyIiB4bWxucz0iIiBlbGVtZW50PSJleGVjdXRpb24iIG1lZGlhVHlwZT0iYXBwbGljYXRpb24vanNvbiIvPgogICAgICAgICAgICAgICAgPC9yZXF1ZXN0PgogICAgICAgICAgICAgICAgPHJlc3BvbnNlPgogICAgICAgICAgICAgICAgICAgIDxyZXByZXNlbnRhdGlvbiBtZWRpYVR5cGU9ImFwcGxpY2F0aW9uL2pzb24iLz4KICAgICAgICAgICAgICAgIDwvcmVzcG9uc2U+CiAgICAgICAgICAgIDwvbWV0aG9kPgogICAgICAgICAgICA8bWV0aG9kIGlkPSJkZWxldGVFeGVjdXRpb25Gb3JUYXNrSWQiIG5hbWU9IkRFTEVURSI+CiAgICAgICAgICAgICAgICA8cmVzcG9uc2U+CiAgICAgICAgICAgICAgICAgICAgPHJlcHJlc2VudGF0aW9uIG1lZGlhVHlwZT0iYXBwbGljYXRpb24vanNvbiIvPgogICAgICAgICAgICAgICAgPC9yZXNwb25zZT4KICAgICAgICAgICAgPC9tZXRob2Q+CiAgICAgICAgPC9yZXNvdXJjZT4KICAgIDwvcmVzb3VyY2VzPgo8L2FwcGxpY2F0aW9uPgo=" 
.15:27:40.987 [http-nio-8080-exec-11] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting PUT for path tasks/b/execution 
.15:27:40.991 [http-nio-8080-exec-11] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "MESSAGE",
  "payload" : {
    "text" : "Execution submitted.",
    "additionalResources" : [ ],
    "debugContent" : null
  }
} 
.15:27:40.992 [pool-3-thread-1] INFO  o.apache.solr.core.SolrCore.Request - [websearch]  webapp=null path=/select params={q=id:gardens\+of\+the\+moon\+steven\+erikson\+malazan\+book\+of\+the\+fallen&fl=id,value} hits=1 status=0 QTime=1 
.15:27:41.009 [pool-3-thread-1] INFO  o.apache.solr.core.SolrCore.Request - [websearch]  webapp=null path=/select params={q=id:deadhouse\+gates\+steven\+erikson\+malazan\+book\+of\+the\+fallen&fl=id,value} hits=1 status=0 QTime=0 
.15:27:41.035 [pool-3-thread-1] INFO  o.apache.solr.core.SolrCore.Request - [entity]  webapp=null path=/select params={q=id:Gardens\+of\+the\+Moon&fl=id,value} hits=1 status=0 QTime=0 
.15:27:41.139 [http-nio-8080-exec-13] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path tasks 
.15:27:41.159 [http-nio-8080-exec-13] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : [ {
    "id" : "a",
    "description" : "a",
    "created" : "2016-11-17 15:16",
    "configuration" : {
      "input" : "Books-v1.csv",
      "feedback" : {
        "subjectColumnPositions" : { },
        "columnIgnores" : [ ],
        "classifications" : [ ],
        "columnAmbiguities" : [ ],
        "ambiguities" : [ ],
        "disambiguations" : [ ],
        "columnRelations" : [ ]
      },
      "primaryBase" : {
        "name" : "DBpedia"
      }
    },
    "state" : "ERROR"
  }, {
    "id" : "b",
    "description" : "b",
    "created" : "2016-11-17 15:27",
    "configuration" : {
      "input" : "Books-v1.csv",
      "feedback" : {
        "subjectColumnPositions" : { },
        "columnIgnores" : [ ],
        "classifications" : [ ],
        "columnAmbiguities" : [ ],
        "ambiguities" : [ ],
        "disambiguations" : [ ],
        "columnRelations" : [ ]
      },
      "primaryBase" : {
        "name" : "DBpedia"
      }
    },
    "state" : "RUNNING"
  } ]
} 
.15:27:44.220 [http-nio-8080-exec-14] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path tasks/b/state 
.15:27:44.222 [http-nio-8080-exec-14] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : "RUNNING"
} 
.15:27:49.282 [http-nio-8080-exec-16] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path tasks/b/state 
.15:27:49.283 [http-nio-8080-exec-16] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : "RUNNING"
} 
.15:27:52.082 [http-nio-8080-exec-17] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path tasks/b/state 
.15:27:52.083 [http-nio-8080-exec-17] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : "RUNNING"
} 
.15:27:55.078 [http-nio-8080-exec-18] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path tasks/b/state 
.15:27:55.079 [http-nio-8080-exec-18] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : "RUNNING"
} 
.15:27:59.195 [http-nio-8080-exec-19] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path tasks/b/state 
.15:27:59.196 [http-nio-8080-exec-19] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : "RUNNING"
} 
.15:28:02.079 [http-nio-8080-exec-15] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path tasks/b/state 
.15:28:02.081 [http-nio-8080-exec-15] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : "RUNNING"
} 
.15:28:06.192 [http-nio-8080-exec-12] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path tasks/b/state 
.15:28:06.194 [http-nio-8080-exec-12] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : "RUNNING"
} 
.15:28:09.079 [http-nio-8080-exec-10] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path tasks/b/state 
.15:28:09.080 [http-nio-8080-exec-10] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : "RUNNING"
} 
.15:28:13.184 [http-nio-8080-exec-11] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path tasks/b/state 
.15:28:13.185 [http-nio-8080-exec-11] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : "RUNNING"
} 
.15:28:15.187 [http-nio-8080-exec-13] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path tasks/b/state 
.15:28:15.189 [http-nio-8080-exec-13] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : "RUNNING"
} 
.15:28:18.188 [http-nio-8080-exec-14] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path tasks/b/state 
.15:28:18.190 [http-nio-8080-exec-14] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : "RUNNING"
} 
.15:28:23.352 [http-nio-8080-exec-16] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path tasks/b/state 
.15:28:23.354 [http-nio-8080-exec-16] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : "RUNNING"
} 
.15:28:25.980 [http-nio-8080-exec-17] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path tasks/b/state 
.15:28:25.981 [http-nio-8080-exec-17] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : "RUNNING"
} 
.15:28:30.245 [http-nio-8080-exec-18] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path tasks/b/state 
.15:28:30.247 [http-nio-8080-exec-18] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : "RUNNING"
} 
.15:28:33.114 [http-nio-8080-exec-19] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path tasks/b/state 
.15:28:33.116 [http-nio-8080-exec-19] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : "RUNNING"
} 
.15:28:37.185 [http-nio-8080-exec-15] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path tasks/b/state 
.15:28:37.188 [http-nio-8080-exec-15] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : "RUNNING"
} 
.15:28:39.277 [http-nio-8080-exec-12] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path tasks/b/state 
.15:28:39.279 [http-nio-8080-exec-12] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : "RUNNING"
} 
.15:28:42.271 [http-nio-8080-exec-10] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path tasks/b/state 
.15:28:42.274 [http-nio-8080-exec-10] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : "RUNNING"
} 
.15:28:45.280 [http-nio-8080-exec-11] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path tasks/b/state 
.15:28:45.282 [http-nio-8080-exec-11] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : "RUNNING"
} 
.15:28:48.883 [http-nio-8080-exec-13] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path tasks/b/state 
.15:28:48.886 [http-nio-8080-exec-13] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : "RUNNING"
} 
.15:28:53.429 [http-nio-8080-exec-14] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path tasks/b/state 
.15:28:53.430 [http-nio-8080-exec-14] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : "RUNNING"
} 
.15:28:56.090 [http-nio-8080-exec-16] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path tasks/b/state 
.15:28:56.091 [http-nio-8080-exec-16] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : "RUNNING"
} 
.15:29:01.163 [http-nio-8080-exec-17] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Requesting GET for path tasks/b/state 
.15:29:01.164 [http-nio-8080-exec-17] DEBUG c.c.m.x.o.a.r.f.LoggingResponseFilter - Reply {
  "status" : 200,
  "type" : "DATA",
  "payload" : "ERROR"
}
brodecva commented 7 years ago

I define new task, run it. Then, when observing logs in tomcat (catalina.out), I got the log as below. But from that, I do not know where the problem was. So ideally the service returning status of the execution should provide some more detail if there is an error state. Could be something low level (like the exception) to start with, so that consumer of such service can see what happened.

I agree, although the exception is eventually logged (albeit abridged as a part of reply message) when you attempt to get the result from the future that does the processing in its own thread.

I will investigate why the logging does not work for the separate processing thread, or if it is even done.

tomas-knap commented 7 years ago

The problem is that TableMinerPlusFactory silently consumes any errors which occur - see TableMinerPlusFactory:99. Such exception must be propagated to REST API, so that it can be provided together with the /task/x/result in some "detail" field (so that the caller does not get only info that there was "ERROR".)

brodecva commented 7 years ago

The problem is that TableMinerPlusFactory silently consumes any errors which occur - see TableMinerPlusFactory:99. Such exception must be propagated to REST API, so that it can be provided together with the /task/x/result in some "detail" field (so that the caller does not get only info that there was "ERROR".)

I have a bad feeling that is not the first time we encouter this error. Fixing right away.

brodecva commented 7 years ago

The problem is that TableMinerPlusFactory silently consumes any errors which occur - see TableMinerPlusFactory:99. Such exception must be propagated to REST API, so that it can be provided together with the /task/x/result in some "detail" field (so that the caller does not get only info that there was "ERROR".)

I have a bad feeling that is not the first time we encouter this error. Fixing right away.

Should be fixed now. At least in the sense that the exceptions are not swallowed.