Uploaded image for project: 'Apache Ozone'
  1. Apache Ozone
  2. HDDS-407

ozone logs are written to ozone.log.<DATE> instead of ozone.log

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Resolved
    • Major
    • Resolution: Cannot Reproduce
    • None
    • None
    • Ozone Client
    • None

    Description

      Please refer below details 

      ozone related logs are written to ozone.log.2018-09-05 instead of ozone.log. Also, please check the timestamps of the logs. The cluster was created 

      [root@ctr-e138-1518143905142-459606-01-000002 logs]# ls -lhart /root/hadoop_trunk/ozone-0.2.1-SNAPSHOT/logs/
      total 968K
      drwxr-xr-x 9 root root 4.0K Sep 5 10:04 ..
      -rw-r--r-- 1 root root 0 Sep 5 10:04 fairscheduler-statedump.log
      -rw-r--r-- 1 root root 17K Sep 5 10:05 hadoop-root-om-ctr-e138-1518143905142-459606-01-000002.hwx.site.out.1
      -rw-r--r-- 1 root root 16K Sep 5 10:10 hadoop-root-om-ctr-e138-1518143905142-459606-01-000002.hwx.site.out
      -rw-r--r-- 1 root root 11K Sep 5 10:10 hadoop-root-om-ctr-e138-1518143905142-459606-01-000002.hwx.site.log
      -rw-r--r-- 1 root root 17K Sep 6 05:42 hadoop-root-datanode-ctr-e138-1518143905142-459606-01-000002.hwx.site.out
      -rw-r--r-- 1 root root 2.1K Sep 6 13:20 ozone.log
      -rw-r--r-- 1 root root 67K Sep 6 13:22 hadoop-root-datanode-ctr-e138-1518143905142-459606-01-000002.hwx.site.log
      drwxr-xr-x 2 root root 4.0K Sep 6 13:31 .
      -rw-r--r-- 1 root root 811K Sep 6 13:39 ozone.log.2018-09-05
      [root@ctr-e138-1518143905142-459606-01-000002 logs]# date
      Thu Sep 6 13:39:47 UTC 2018

       

      tail of ozone.log

      [root@ctr-e138-1518143905142-459606-01-000002 logs]# tail -f ozone.log
      2018-09-06 10:51:56,616 [IPC Server handler 13 on 9889] DEBUG (KeyManagerImpl.java:255) - Key 0file allocated in volume test-vol2 bucket test-bucket2
      2018-09-06 10:52:18,570 [IPC Server handler 9 on 9889] DEBUG (KeyManagerImpl.java:255) - Key 0file1 allocated in volume test-vol2 bucket test-bucket2
      2018-09-06 10:52:32,256 [IPC Server handler 12 on 9889] DEBUG (KeyManagerImpl.java:255) - Key 0file2 allocated in volume test-vol2 bucket test-bucket2
      2018-09-06 10:53:11,008 [IPC Server handler 14 on 9889] DEBUG (KeyManagerImpl.java:255) - Key 0file2 allocated in volume test-vol2 bucket test-bucket2
      2018-09-06 10:53:28,316 [IPC Server handler 10 on 9889] DEBUG (KeyManagerImpl.java:255) - Key 0file2 allocated in volume test-vol2 bucket test-bucket2
      2018-09-06 10:53:39,509 [IPC Server handler 17 on 9889] DEBUG (KeyManagerImpl.java:255) - Key 0file3 allocated in volume test-vol2 bucket test-bucket2
      2018-09-06 11:31:02,388 [IPC Server handler 19 on 9889] DEBUG (KeyManagerImpl.java:255) - Key 2GBFILE allocated in volume test-vol2 bucket test-bucket2
      2018-09-06 11:32:44,269 [IPC Server handler 12 on 9889] DEBUG (KeyManagerImpl.java:255) - Key 2GBFILE_1 allocated in volume test-vol2 bucket test-bucket2
      2018-09-06 13:17:33,408 [IPC Server handler 16 on 9889] DEBUG (KeyManagerImpl.java:255) - Key FILEWITHZEROS allocated in volume test-vol2 bucket test-bucket2
      2018-09-06 13:20:13,897 [IPC Server handler 15 on 9889] DEBUG (KeyManagerImpl.java:255) - Key FILEWITHZEROS1 allocated in volume test-vol2 bucket test-bucket2

       

      tail of ozone.log.2018-09-05:

      root@ctr-e138-1518143905142-459606-01-000002 logs]# tail -50 ozone.log.2018-09-05
      2018-09-06 13:28:57,866 [BlockDeletingService#8] DEBUG (TopNOrderedContainerDeletionChoosingPolicy.java:79) - Stop looking for next container, there is no pending deletion block contained in remaining containers.
      2018-09-06 13:29:07,816 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3266
      2018-09-06 13:29:13,687 [Datanode ReportManager Thread - 0] DEBUG (ContainerSet.java:191) - Starting container report iteration.
      2018-09-06 13:29:37,816 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3267
      2018-09-06 13:29:57,866 [BlockDeletingService#8] DEBUG (TopNOrderedContainerDeletionChoosingPolicy.java:79) - Stop looking for next container, there is no pending deletion block contained in remaining containers.
      2018-09-06 13:30:07,816 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3268
      2018-09-06 13:30:19,186 [Datanode ReportManager Thread - 0] DEBUG (ContainerSet.java:191) - Starting container report iteration.
      2018-09-06 13:30:37,816 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3269
      2018-09-06 13:30:57,866 [BlockDeletingService#8] DEBUG (TopNOrderedContainerDeletionChoosingPolicy.java:79) - Stop looking for next container, there is no pending deletion block contained in remaining containers.
      2018-09-06 13:31:07,816 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3270
      2018-09-06 13:31:19,935 [Datanode ReportManager Thread - 0] DEBUG (ContainerSet.java:191) - Starting container report iteration.
      2018-09-06 13:31:37,817 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3271
      2018-09-06 13:31:57,867 [BlockDeletingService#8] DEBUG (TopNOrderedContainerDeletionChoosingPolicy.java:79) - Stop looking for next container, there is no pending deletion block contained in remaining containers.
      2018-09-06 13:32:07,817 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3272
      2018-09-06 13:32:28,898 [Datanode ReportManager Thread - 0] DEBUG (ContainerSet.java:191) - Starting container report iteration.
      2018-09-06 13:32:37,817 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3273
      2018-09-06 13:32:57,867 [BlockDeletingService#8] DEBUG (TopNOrderedContainerDeletionChoosingPolicy.java:79) - Stop looking for next container, there is no pending deletion block contained in remaining containers.
      2018-09-06 13:33:07,817 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3274
      2018-09-06 13:33:37,818 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3275
      2018-09-06 13:33:57,868 [BlockDeletingService#8] DEBUG (TopNOrderedContainerDeletionChoosingPolicy.java:79) - Stop looking for next container, there is no pending deletion block contained in remaining containers.
      2018-09-06 13:34:07,818 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3276
      2018-09-06 13:34:22,773 [Datanode ReportManager Thread - 2] DEBUG (ContainerSet.java:191) - Starting container report iteration.
      2018-09-06 13:34:37,818 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3277
      2018-09-06 13:34:57,868 [BlockDeletingService#8] DEBUG (TopNOrderedContainerDeletionChoosingPolicy.java:79) - Stop looking for next container, there is no pending deletion block contained in remaining containers.
      2018-09-06 13:35:07,818 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3278
      2018-09-06 13:35:37,818 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3279
      2018-09-06 13:35:57,869 [BlockDeletingService#8] DEBUG (TopNOrderedContainerDeletionChoosingPolicy.java:79) - Stop looking for next container, there is no pending deletion block contained in remaining containers.
      2018-09-06 13:36:07,820 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3280
      2018-09-06 13:36:20,425 [Datanode ReportManager Thread - 0] DEBUG (ContainerSet.java:191) - Starting container report iteration.
      2018-09-06 13:36:37,820 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3281
      2018-09-06 13:36:57,869 [BlockDeletingService#8] DEBUG (TopNOrderedContainerDeletionChoosingPolicy.java:79) - Stop looking for next container, there is no pending deletion block contained in remaining containers.
      2018-09-06 13:37:07,820 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3282
      2018-09-06 13:37:36,895 [Datanode ReportManager Thread - 0] DEBUG (ContainerSet.java:191) - Starting container report iteration.
      2018-09-06 13:37:37,820 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3283
      2018-09-06 13:37:57,869 [BlockDeletingService#8] DEBUG (TopNOrderedContainerDeletionChoosingPolicy.java:79) - Stop looking for next container, there is no pending deletion block contained in remaining containers.
      2018-09-06 13:38:07,820 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3284
      2018-09-06 13:38:37,820 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3285
      2018-09-06 13:38:57,870 [BlockDeletingService#8] DEBUG (TopNOrderedContainerDeletionChoosingPolicy.java:79) - Stop looking for next container, there is no pending deletion block contained in remaining containers.
      2018-09-06 13:39:07,821 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3286
      2018-09-06 13:39:15,256 [Datanode ReportManager Thread - 1] DEBUG (ContainerSet.java:191) - Starting container report iteration.
      2018-09-06 13:39:37,821 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3287
      2018-09-06 13:39:57,870 [BlockDeletingService#8] DEBUG (TopNOrderedContainerDeletionChoosingPolicy.java:79) - Stop looking for next container, there is no pending deletion block contained in remaining containers.
      2018-09-06 13:40:07,823 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3288
      2018-09-06 13:40:29,575 [Datanode ReportManager Thread - 1] DEBUG (ContainerSet.java:191) - Starting container report iteration.
      2018-09-06 13:40:37,823 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3289
      2018-09-06 13:40:57,871 [BlockDeletingService#8] DEBUG (TopNOrderedContainerDeletionChoosingPolicy.java:79) - Stop looking for next container, there is no pending deletion block contained in remaining containers.
      2018-09-06 13:41:07,824 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3290
      2018-09-06 13:41:37,824 [Datanode State Machine Thread - 0] DEBUG (DatanodeStateMachine.java:145) - Executing cycle Number : 3291
      2018-09-06 13:41:57,871 [BlockDeletingService#8] DEBUG (TopNOrderedContainerDeletionChoosingPolicy.java:79) - Stop looking for next container, there is no pending deletion block contained in remaining containers.
      2018-09-06 13:42:00,662 [Datanode ReportManager Thread - 2] DEBUG (ContainerSet.java:191) - Starting container report iteration.

       

      ozone manager running on the system :

      [root@ctr-e138-1518143905142-459606-01-000002 logs]# ps -ef | grep ozone
      root 2011967 1 0 Sep05 ? 00:03:03 /base/tools/jdk1.8.0_112/bin/java -Dproc_om -Djava.net.preferIPv4Stack=true -Dhadoop.log.dir=/root/hadoop_trunk/ozone-0.2.1-SNAPSHOT/logs -Dhadoop.log.file=hadoop-root-om-ctr-e138-1518143905142-459606-01-000002.hwx.site.log -Dhadoop.home.dir=/root/hadoop_trunk/ozone-0.2.1-SNAPSHOT -Dhadoop.id.str=root -Dhadoop.root.logger=INFO,RFA -Dhadoop.policy.file=hadoop-policy.xml -Dhadoop.security.logger=INFO,NullAppender org.apache.hadoop.ozone.om.OzoneManager
      root 2014398 1 0 Sep05 ? 00:09:38 /base/tools/jdk1.8.0_112/bin/java -Dproc_datanode -Djava.net.preferIPv4Stack=true -Dhadoop.log.dir=/root/hadoop_trunk/ozone-0.2.1-SNAPSHOT/logs -Dhadoop.log.file=hadoop-root-datanode-ctr-e138-1518143905142-459606-01-000002.hwx.site.log -Dhadoop.home.dir=/root/hadoop_trunk/ozone-0.2.1-SNAPSHOT -Dhadoop.id.str=root -Dhadoop.root.logger=INFO,RFA -Dhadoop.policy.file=hadoop-policy.xml -Dhadoop.security.logger=INFO,NullAppender org.apache.hadoop.ozone.HddsDatanodeService
      root 2374538 2341272 0 13:43 pts/2 00:00:00 grep --color=auto ozone

      Attachments

        Activity

          People

            dineshchitlangia Dinesh Chitlangia
            nilotpalnandi Nilotpal Nandi
            Votes:
            1 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: