[jira] [Commented] (HIVE-17158) BeeLine Query Log and Query Result print order is not defined

["Peter Vary (JIRA)" <ji...@apache.org>]

    [ https://issues.apache.org/jira/browse/HIVE-17158?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16098296#comment-16098296 ] 

Peter Vary commented on HIVE-17158:
-----------------------------------

The root cause of the issue is that if the LogRunnable is interrupted before started then there is no InterruptedException thrown, and the {{showRemainingLogsIfAny}} is not called. 

{code}
  private Runnable createLogRunnable(final Statement statement) {
    if (statement instanceof HiveStatement) {
      final HiveStatement hiveStatement = (HiveStatement) statement;

      Runnable runnable = new Runnable() {
        @Override
        public void run() {
          while (hiveStatement.hasMoreLogs() && !Thread.currentThread().isInterrupted()) {
            try {
              // fetch the log periodically and output to beeline console
              for (String log : hiveStatement.getQueryLog()) {
                if (!beeLine.isTestMode()) {
                  beeLine.info(log);
                } else {
                  // In test mode print the logs to the output
                  beeLine.output(log);
                }
              }
              Thread.sleep(DEFAULT_QUERY_PROGRESS_INTERVAL);
            } catch (SQLException e) {
              beeLine.error(new SQLWarning(e));
              return;
            } catch (InterruptedException e) {
              beeLine.debug("Getting log thread is interrupted, since query is done!");
              showRemainingLogsIfAny(statement);              <-- We expect to print the logs here, but if no exception, no logs
              return;
            }
          }
        }
      };
      return runnable;
    } else {
[..]
    }
  }
{code}

The log printed when the ResultSet is queried, or in the finally stage.
{code}
          do {
            ResultSet rs = stmnt.getResultSet();
            try {
              int count = beeLine.print(rs);
              long end = System.currentTimeMillis();

              beeLine.info(
                  beeLine.loc("rows-selected", count) + " " + beeLine.locElapsedTime(end - start));
            } finally {
              if (logThread != null) {
                logThread.join(DEFAULT_QUERY_PROGRESS_THREAD_TIMEOUT);
                showRemainingLogsIfAny(stmnt);
                logThread = null;
              }
              rs.close();
            }
          } while (BeeLine.getMoreResults(stmnt));
{code}

{code}
      } finally {
        if (logThread != null) {
          if (!logThread.isInterrupted()) {
            logThread.interrupt();
          }
          logThread.join(DEFAULT_QUERY_PROGRESS_THREAD_TIMEOUT);
          showRemainingLogsIfAny(stmnt);
        }
        if (stmnt != null) {
          stmnt.close();
        }
      }
{code}

> BeeLine Query Log and Query Result print order is not defined
> -------------------------------------------------------------
>
>                 Key: HIVE-17158
>                 URL: https://issues.apache.org/jira/browse/HIVE-17158
>             Project: Hive
>          Issue Type: Bug
>          Components: Beeline, Testing Infrastructure
>    Affects Versions: 3.0.0
>            Reporter: Peter Vary
>            Assignee: Peter Vary
>
> The output of the BeeLine tests is sometimes flaky, especially if the query is a fast one
> The output is sometime this:
> {code}
> PREHOOK: query: select explode(array('a', 'b'))
> PREHOOK: type: QUERY
> PREHOOK: Input: _dummy_database@_dummy_table
> #### A masked pattern was here ####
> POSTHOOK: query: select explode(array('a', 'b'))
> POSTHOOK: type: QUERY
> POSTHOOK: Input: _dummy_database@_dummy_table
> #### A masked pattern was here ####
> a
> b
> {code}
> Sometime this:
> {code}
> a
> b
> PREHOOK: query: select explode(array('a', 'b'))
> PREHOOK: type: QUERY
> PREHOOK: Input: _dummy_database@_dummy_table
> #### A masked pattern was here ####
> POSTHOOK: query: select explode(array('a', 'b'))
> POSTHOOK: type: QUERY
> POSTHOOK: Input: _dummy_database@_dummy_table
> #### A masked pattern was here ####
> {code}
> Notice, that the actual query result is either before, or after the stuff printed by the hooks.



--
This message was sent by Atlassian JIRA
(v6.4.14#64029)