See http://hudson.zones.apache.org/hudson/job/Hadoop-trunk/412/changes
Changes:
[dhruba] HADOOP-2655. Copy on write for data and metadata files in the
presence of snapshots. Needed for supporting appends to HDFS
files. (dhruba)
[dhruba] HADOOP-2873. Fixed bad disk format introduced by HADOOP-2345.
Disk layout version changed from -12 to -13. See changelist 630992
(dhruba)
[dhruba] HADOOP-2873. Fixed bad disk format introduced by HADOOP-2345.
Disk layout version changed from -12 to -13. (dhruba)
[dhruba] HADOOP-2345. Fixed bad disk format introduced by HADOOP-2345.
Disk layout version changed from -12 to -13. (dhruba)
------------------------------------------
[...truncated 84379 lines...]
[junit] 2008-02-26 12:03:33,388 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 7 on 56795,
ugi=null
[junit] 2008-02-26 12:03:33,389 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 7 on 56795,
ugi=null
[junit] 2008-02-26 12:03:33,390 INFO dfs.DataNode
(DataNode.java:offerService(647)) - BlockReport of 0 blocks got processed in 3
msecs
[junit] 2008-02-26 12:03:33,406 INFO dfs.DataNode
(FSDataset.java:registerMBean(936)) - Registered FSDatasetStatusMBean
[junit] 2008-02-26 12:03:33,407 INFO dfs.DataNode
(DataNode.java:startDataNode(250)) - Opened server at 56801
[junit] 2008-02-26 12:03:33,408 INFO dfs.DataNode
(DataNode.java:startDataNode(272)) - Balancing bandwith is 1048576 bytes/s
[junit] 2008-02-26 12:03:33,426 INFO http.HttpServer
(HttpServer.java:doStart(729)) - Version Jetty/5.1.4
[junit] 2008-02-26 12:03:33,533 INFO util.Container
(Container.java:start(74)) - Started [EMAIL PROTECTED]
[junit] 2008-02-26 12:03:33,536 INFO util.Container
(Container.java:start(74)) - Started WebApplicationContext[/,/]
[junit] 2008-02-26 12:03:33,537 INFO util.Container
(Container.java:start(74)) - Started HttpContext[/logs,/logs]
[junit] 2008-02-26 12:03:33,537 INFO util.Container
(Container.java:start(74)) - Started HttpContext[/static,/static]
[junit] 2008-02-26 12:03:33,539 INFO http.SocketListener
(SocketListener.java:start(204)) - Started SocketListener on 0.0.0.0:56802
[junit] 2008-02-26 12:03:33,540 INFO util.Container
(Container.java:start(74)) - Started [EMAIL PROTECTED]
[junit] 2008-02-26 12:03:33,542 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 5 on 56795,
ugi=null
[junit] 2008-02-26 12:03:33,543 INFO dfs.StateChange
(FSNamesystem.java:registerDatanode(1889)) - BLOCK*
NameSystem.registerDatanode: node registration from 127.0.0.1:56801 storage
DS-769007830-140.211.11.106-56801-1204027413542
[junit] 2008-02-26 12:03:33,544 INFO net.NetworkTopology
(NetworkTopology.java:add(319)) - Adding a new node:
/default-rack/127.0.0.1:56801
[junit] 2008-02-26 12:03:33,544 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 5 on 56795,
ugi=null
[junit] 2008-02-26 12:03:33,747 INFO dfs.DataNode
(DataNode.java:register(437)) - New storage id
DS-769007830-140.211.11.106-56801-1204027413542 is assigned to data-node
127.0.0.1:56801
[junit] 2008-02-26 12:03:33,748 INFO jvm.JvmMetrics
(JvmMetrics.java:init(62)) - Cannot initialize JVM Metrics with
processName=DataNode, sessionId=null - already initialized
[junit] 2008-02-26 12:03:33,751 INFO dfs.DataNode
(DataNode.java:run(2416)) - 127.0.0.1:56801In DataNode.run, data =
FSDataset{dirpath='/zonestorage/hudson/home/hudson/hudson/jobs/Hadoop-trunk/workspace/trunk/build/test/data/dfs/data/data3/current,/zonestorage/hudson/home/hudson/hudson/jobs/Hadoop-trunk/workspace/trunk/build/test/data/dfs/data/data4/current'}
[junit] Starting DataNode 2 with dfs.data.dir:
/zonestorage/hudson/home/hudson/hudson/jobs/Hadoop-trunk/workspace/trunk/build/test/data/dfs/data/data5,/zonestorage/hudson/home/hudson/hudson/jobs/Hadoop-trunk/workspace/trunk/build/test/data/dfs/data/data6
[junit] 2008-02-26 12:03:33,752 INFO dfs.DataNode
(DataNode.java:offerService(565)) - using BLOCKREPORT_INTERVAL of 3299337msec
Initial delay: 0msec
[junit] 2008-02-26 12:03:33,788 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 3 on 56795,
ugi=null
[junit] 2008-02-26 12:03:33,789 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 3 on 56795,
ugi=null
[junit] 2008-02-26 12:03:33,791 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 0 on 56795,
ugi=null
[junit] 2008-02-26 12:03:33,792 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 0 on 56795,
ugi=null
[junit] 2008-02-26 12:03:33,794 INFO dfs.Storage
(DataStorage.java:recoverTransitionRead(117)) - Storage directory
/zonestorage/hudson/home/hudson/hudson/jobs/Hadoop-trunk/workspace/trunk/build/test/data/dfs/data/data5
is not formatted.
[junit] 2008-02-26 12:03:33,795 INFO dfs.Storage
(DataStorage.java:recoverTransitionRead(118)) - Formatting ...
[junit] 2008-02-26 12:03:34,109 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 2 on 56795,
ugi=null
[junit] 2008-02-26 12:03:34,111 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 2 on 56795,
ugi=null
[junit] 2008-02-26 12:03:34,114 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 4 on 56795,
ugi=null
[junit] 2008-02-26 12:03:34,115 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 4 on 56795,
ugi=null
[junit] 2008-02-26 12:03:34,115 INFO dfs.DataNode
(DataNode.java:offerService(647)) - BlockReport of 0 blocks got processed in 2
msecs
[junit] 2008-02-26 12:03:34,169 INFO dfs.Storage
(DataStorage.java:recoverTransitionRead(117)) - Storage directory
/zonestorage/hudson/home/hudson/hudson/jobs/Hadoop-trunk/workspace/trunk/build/test/data/dfs/data/data6
is not formatted.
[junit] 2008-02-26 12:03:34,170 INFO dfs.Storage
(DataStorage.java:recoverTransitionRead(118)) - Formatting ...
[junit] 2008-02-26 12:03:34,603 INFO dfs.DataNode
(FSDataset.java:registerMBean(936)) - Registered FSDatasetStatusMBean
[junit] 2008-02-26 12:03:34,603 INFO dfs.DataNode
(DataNode.java:startDataNode(250)) - Opened server at 56804
[junit] 2008-02-26 12:03:34,604 INFO dfs.DataNode
(DataNode.java:startDataNode(272)) - Balancing bandwith is 1048576 bytes/s
[junit] 2008-02-26 12:03:34,609 INFO http.HttpServer
(HttpServer.java:doStart(729)) - Version Jetty/5.1.4
[junit] 2008-02-26 12:03:34,793 INFO util.Container
(Container.java:start(74)) - Started [EMAIL PROTECTED]
[junit] 2008-02-26 12:03:34,796 INFO util.Container
(Container.java:start(74)) - Started WebApplicationContext[/,/]
[junit] 2008-02-26 12:03:34,796 INFO util.Container
(Container.java:start(74)) - Started HttpContext[/logs,/logs]
[junit] 2008-02-26 12:03:34,797 INFO util.Container
(Container.java:start(74)) - Started HttpContext[/static,/static]
[junit] 2008-02-26 12:03:34,799 INFO http.SocketListener
(SocketListener.java:start(204)) - Started SocketListener on 0.0.0.0:56805
[junit] 2008-02-26 12:03:34,800 INFO util.Container
(Container.java:start(74)) - Started [EMAIL PROTECTED]
[junit] 2008-02-26 12:03:34,802 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 6 on 56795,
ugi=null
[junit] 2008-02-26 12:03:34,803 INFO dfs.StateChange
(FSNamesystem.java:registerDatanode(1889)) - BLOCK*
NameSystem.registerDatanode: node registration from 127.0.0.1:56804 storage
DS-1571575077-140.211.11.106-56804-1204027414802
[junit] 2008-02-26 12:03:34,803 INFO net.NetworkTopology
(NetworkTopology.java:add(319)) - Adding a new node:
/default-rack/127.0.0.1:56804
[junit] 2008-02-26 12:03:34,804 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 6 on 56795,
ugi=null
[junit] 2008-02-26 12:03:34,860 INFO dfs.DataNode
(DataNode.java:register(437)) - New storage id
DS-1571575077-140.211.11.106-56804-1204027414802 is assigned to data-node
127.0.0.1:56804
[junit] 2008-02-26 12:03:34,861 INFO jvm.JvmMetrics
(JvmMetrics.java:init(62)) - Cannot initialize JVM Metrics with
processName=DataNode, sessionId=null - already initialized
[junit] 2008-02-26 12:03:34,864 DEBUG security.UserGroupInformation
(PermissionChecker.java:<init>(40)) - ugi=hudson,hudson
[junit] 2008-02-26 12:03:34,864 INFO dfs.DataNode
(DataNode.java:run(2416)) - 127.0.0.1:56804In DataNode.run, data =
FSDataset{dirpath='/zonestorage/hudson/home/hudson/hudson/jobs/Hadoop-trunk/workspace/trunk/build/test/data/dfs/data/data5/current,/zonestorage/hudson/home/hudson/hudson/jobs/Hadoop-trunk/workspace/trunk/build/test/data/dfs/data/data6/current'}
[junit] 2008-02-26 12:03:34,882 INFO dfs.DataNode
(DataNode.java:offerService(565)) - using BLOCKREPORT_INTERVAL of 3252016msec
Initial delay: 0msec
[junit] 2008-02-26 12:03:34,919 DEBUG security.UserGroupInformation
(UnixUserGroupInformation.java:login(269)) - Unix Login: hudson,hudson
[junit] 2008-02-26 12:03:34,924 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 8 on 56795,
ugi=hudson,hudson
[junit] 2008-02-26 12:03:34,925 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 8 on 56795,
ugi=null
[junit] 2008-02-26 12:03:34,927 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 1 on 56795,
ugi=hudson,hudson
[junit] 2008-02-26 12:03:34,927 DEBUG security.UserGroupInformation
(PermissionChecker.java:<init>(40)) - ugi=hudson,hudson
[junit] 2008-02-26 12:03:34,928 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 1 on 56795,
ugi=null
[junit] 2008-02-26 12:03:35,079 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 9 on 56795,
ugi=null
[junit] 2008-02-26 12:03:35,082 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 9 on 56795,
ugi=null
[junit] 2008-02-26 12:03:35,085 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 7 on 56795,
ugi=null
[junit] 2008-02-26 12:03:35,085 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 7 on 56795,
ugi=null
[junit] 2008-02-26 12:03:35,086 INFO dfs.DataNode
(DataNode.java:offerService(647)) - BlockReport of 0 blocks got processed in 3
msecs
[junit] 2008-02-26 12:03:35,938 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 5 on 56795,
ugi=hudson,hudson
[junit] 2008-02-26 12:03:35,939 DEBUG security.UserGroupInformation
(PermissionChecker.java:<init>(40)) - ugi=hudson,hudson
[junit] 2008-02-26 12:03:35,967 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 5 on 56795,
ugi=null
[junit] 2008-02-26 12:03:35,969 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 3 on 56795,
ugi=hudson,hudson
[junit] 2008-02-26 12:03:35,970 DEBUG security.UserGroupInformation
(PermissionChecker.java:<init>(40)) - ugi=hudson,hudson
[junit] 2008-02-26 12:03:35,970 DEBUG security.UserGroupInformation
(PermissionChecker.java:<init>(40)) - ugi=hudson,hudson
[junit] 2008-02-26 12:03:35,993 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 3 on 56795,
ugi=null
[junit] 2008-02-26 12:03:35,995 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 0 on 56795,
ugi=hudson,hudson
[junit] 2008-02-26 12:03:35,996 INFO dfs.StateChange
(FSNamesystem.java:allocateBlock(1282)) - BLOCK* NameSystem.allocateBlock:
/data/file1. blk_-8204456889257554070
[junit] 2008-02-26 12:03:35,997 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 0 on 56795,
ugi=null
[junit] 2008-02-26 12:03:36,000 INFO dfs.DataNode
(DataNode.java:writeBlock(1048)) - Receiving block blk_-8204456889257554070
src: /127.0.0.1:56807 dest: /127.0.0.1:56799
[junit] 2008-02-26 12:03:36,003 INFO dfs.DataNode
(DataNode.java:writeBlock(1048)) - Receiving block blk_-8204456889257554070
src: /127.0.0.1:56808 dest: /127.0.0.1:56801
[junit] 2008-02-26 12:03:36,005 INFO dfs.DataNode
(DataNode.java:writeBlock(1048)) - Receiving block blk_-8204456889257554070
src: /127.0.0.1:56809 dest: /127.0.0.1:56804
[junit] 2008-02-26 12:03:36,006 INFO dfs.DataNode
(DataNode.java:writeBlock(1141)) - Datanode 0 forwarding connect ack to
upstream firstbadlink is
[junit] 2008-02-26 12:03:36,008 INFO dfs.DataNode
(DataNode.java:writeBlock(1118)) - Datanode 1 got response for connect ack
from downstream datanode with firstbadlink as
[junit] 2008-02-26 12:03:36,008 INFO dfs.DataNode
(DataNode.java:writeBlock(1141)) - Datanode 1 forwarding connect ack to
upstream firstbadlink is
[junit] 2008-02-26 12:03:36,009 INFO dfs.DataNode
(DataNode.java:writeBlock(1118)) - Datanode 2 got response for connect ack
from downstream datanode with firstbadlink as
[junit] 2008-02-26 12:03:36,009 INFO dfs.DataNode
(DataNode.java:writeBlock(1141)) - Datanode 2 forwarding connect ack to
upstream firstbadlink is
[junit] 2008-02-26 12:03:36,011 INFO dfs.DataNode
(DataNode.java:lastDataNodeRun(1775)) - Received block blk_-8204456889257554070
of size 100 from /127.0.0.1
[junit] 2008-02-26 12:03:36,012 INFO dfs.DataNode
(DataNode.java:run(1860)) - Received block blk_-8204456889257554070 of size 100
from /127.0.0.1
[junit] 2008-02-26 12:03:36,013 INFO dfs.DataNode
(DataNode.java:run(1860)) - Received block blk_-8204456889257554070 of size 100
from /127.0.0.1
[junit] 2008-02-26 12:03:36,014 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 2 on 56795,
ugi=null
[junit] 2008-02-26 12:03:36,015 INFO dfs.StateChange
(FSNamesystem.java:addStoredBlock(2504)) - BLOCK* NameSystem.addStoredBlock:
blockMap updated: 127.0.0.1:56801 is added to blk_-8204456889257554070 size 100
[junit] 2008-02-26 12:03:36,015 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 2 on 56795,
ugi=null
[junit] 2008-02-26 12:03:36,016 INFO dfs.DataNode
(DataNode.java:run(1918)) - PacketResponder 1 for block
blk_-8204456889257554070 terminating
[junit] 2008-02-26 12:03:36,017 INFO dfs.DataNode
(DataNode.java:run(1918)) - PacketResponder 2 for block
blk_-8204456889257554070 terminating
[junit] 2008-02-26 12:03:36,018 INFO dfs.DataNode
(DataNode.java:lastDataNodeRun(1793)) - PacketResponder 0 for block
blk_-8204456889257554070 terminating
[junit] 2008-02-26 12:03:36,019 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 4 on 56795,
ugi=hudson,hudson
[junit] 2008-02-26 12:03:36,093 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 6 on 56795,
ugi=null
[junit] 2008-02-26 12:03:36,093 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 8 on 56795,
ugi=null
[junit] 2008-02-26 12:03:36,094 INFO dfs.StateChange
(FSNamesystem.java:addStoredBlock(2504)) - BLOCK* NameSystem.addStoredBlock:
blockMap updated: 127.0.0.1:56804 is added to blk_-8204456889257554070 size 100
[junit] 2008-02-26 12:03:36,094 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 6 on 56795,
ugi=null
[junit] 2008-02-26 12:03:36,095 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 8 on 56795,
ugi=null
[junit] 2008-02-26 12:03:36,096 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 1 on 56795,
ugi=null
[junit] 2008-02-26 12:03:36,096 INFO dfs.StateChange
(FSNamesystem.java:addStoredBlock(2504)) - BLOCK* NameSystem.addStoredBlock:
blockMap updated: 127.0.0.1:56799 is added to blk_-8204456889257554070 size 100
[junit] 2008-02-26 12:03:36,097 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 1 on 56795,
ugi=null
[junit] 2008-02-26 12:03:36,113 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 4 on 56795,
ugi=null
[junit] 2008-02-26 12:03:36,114 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 9 on 56795,
ugi=hudson,hudson
[junit] 2008-02-26 12:03:36,114 DEBUG security.UserGroupInformation
(PermissionChecker.java:<init>(40)) - ugi=hudson,hudson
[junit] 2008-02-26 12:03:36,143 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 9 on 56795,
ugi=null
[junit] 2008-02-26 12:03:36,162 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 7 on 56795,
ugi=hudson,hudson
[junit] 2008-02-26 12:03:36,163 DEBUG security.UserGroupInformation
(PermissionChecker.java:<init>(40)) - ugi=hudson,hudson
[junit] 2008-02-26 12:03:36,167 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 7 on 56795,
ugi=null
[junit] 2008-02-26 12:03:36,193 INFO dfs.DataNode
(DataNode.java:readBlock(1015)) - 127.0.0.1:56804 Served block
blk_-8204456889257554070 to /127.0.0.1
[junit] 2008-02-26 12:03:36,719 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 5 on 56795,
ugi=Who,group1,group2
[junit] 2008-02-26 12:03:36,720 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 5 on 56795,
ugi=null
[junit] 2008-02-26 12:03:36,721 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 3 on 56795,
ugi=Who,group1,group2
[junit] 2008-02-26 12:03:36,721 DEBUG security.UserGroupInformation
(PermissionChecker.java:<init>(40)) - ugi=Who,group1,group2
[junit] 2008-02-26 12:03:36,722 DEBUG security.UserGroupInformation
(PermissionChecker.java:checkPermission(87)) - ACCESS CHECK: [EMAIL PROTECTED],
doCheckOwner=false, ancestorAccess=WRITE, parentAccess=null, access=null,
subAccess=null
[junit] 2008-02-26 12:03:36,727 INFO ipc.Server (Server.java:run(901)) -
IPC Server handler 3 on 56795, call mkdirs(/data/web2, rwxr-xr-x) from
127.0.0.1:56811: error: org.apache.hadoop.fs.permission.AccessControlException:
Permission denied: user=Who, access=WRITE,
inode="data":hudson:supergroup:rwxr-xr-x
[junit] org.apache.hadoop.fs.permission.AccessControlException: Permission
denied: user=Who, access=WRITE, inode="data":hudson:supergroup:rwxr-xr-x
[junit] at
org.apache.hadoop.dfs.PermissionChecker.check(PermissionChecker.java:173)
[junit] at
org.apache.hadoop.dfs.PermissionChecker.check(PermissionChecker.java:154)
[junit] at
org.apache.hadoop.dfs.PermissionChecker.checkPermission(PermissionChecker.java:102)
[junit] at
org.apache.hadoop.dfs.FSNamesystem.checkPermission(FSNamesystem.java:4035)
[junit] at
org.apache.hadoop.dfs.FSNamesystem.checkAncestorAccess(FSNamesystem.java:4005)
[junit] at
org.apache.hadoop.dfs.FSNamesystem.mkdirsInternal(FSNamesystem.java:1558)
[junit] at
org.apache.hadoop.dfs.FSNamesystem.mkdirs(FSNamesystem.java:1541)
[junit] at org.apache.hadoop.dfs.NameNode.mkdirs(NameNode.java:422)
[junit] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[junit] at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
[junit] at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
[junit] at java.lang.reflect.Method.invoke(Method.java:585)
[junit] at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:409)
[junit] at org.apache.hadoop.ipc.Server$Handler.run(Server.java:899)
[junit] 2008-02-26 12:03:36,729 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 3 on 56795,
ugi=null
[junit] 2008-02-26 12:03:36,733 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 0 on 56795,
ugi=Who,group1,group2
[junit] 2008-02-26 12:03:36,733 DEBUG security.UserGroupInformation
(PermissionChecker.java:<init>(40)) - ugi=Who,group1,group2
[junit] 2008-02-26 12:03:36,733 DEBUG security.UserGroupInformation
(PermissionChecker.java:checkPermission(87)) - ACCESS CHECK: [EMAIL PROTECTED],
doCheckOwner=false, ancestorAccess=null, parentAccess=null, access=null,
subAccess=null
[junit] 2008-02-26 12:03:36,734 DEBUG security.UserGroupInformation
(PermissionChecker.java:<init>(40)) - ugi=Who,group1,group2
[junit] 2008-02-26 12:03:36,734 DEBUG security.UserGroupInformation
(PermissionChecker.java:checkPermission(87)) - ACCESS CHECK: [EMAIL PROTECTED],
doCheckOwner=false, ancestorAccess=WRITE, parentAccess=null, access=null,
subAccess=null
[junit] 2008-02-26 12:03:36,735 INFO ipc.Server (Server.java:run(901)) -
IPC Server handler 0 on 56795, call create(/data/file2, rwxr-xr-x,
DFSClient_-2132005371, true, 3, 67108864) from 127.0.0.1:56811: error:
org.apache.hadoop.fs.permission.AccessControlException: Permission denied:
user=Who, access=WRITE, inode="data":hudson:supergroup:rwxr-xr-x
[junit] org.apache.hadoop.fs.permission.AccessControlException: Permission
denied: user=Who, access=WRITE, inode="data":hudson:supergroup:rwxr-xr-x
[junit] at
org.apache.hadoop.dfs.PermissionChecker.check(PermissionChecker.java:173)
[junit] at
org.apache.hadoop.dfs.PermissionChecker.check(PermissionChecker.java:154)
[junit] at
org.apache.hadoop.dfs.PermissionChecker.checkPermission(PermissionChecker.java:102)
[junit] at
org.apache.hadoop.dfs.FSNamesystem.checkPermission(FSNamesystem.java:4035)
[junit] at
org.apache.hadoop.dfs.FSNamesystem.checkAncestorAccess(FSNamesystem.java:4005)
[junit] at
org.apache.hadoop.dfs.FSNamesystem.startFileInternal(FSNamesystem.java:963)
[junit] at
org.apache.hadoop.dfs.FSNamesystem.startFile(FSNamesystem.java:938)
[junit] at org.apache.hadoop.dfs.NameNode.create(NameNode.java:281)
[junit] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[junit] at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
[junit] at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
[junit] at java.lang.reflect.Method.invoke(Method.java:585)
[junit] at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:409)
[junit] at org.apache.hadoop.ipc.Server$Handler.run(Server.java:899)
[junit] 2008-02-26 12:03:36,735 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 0 on 56795,
ugi=null
[junit] 2008-02-26 12:03:36,737 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 2 on 56795,
ugi=Who,group1,group2
[junit] 2008-02-26 12:03:36,737 DEBUG security.UserGroupInformation
(PermissionChecker.java:<init>(40)) - ugi=Who,group1,group2
[junit] 2008-02-26 12:03:36,738 DEBUG security.UserGroupInformation
(PermissionChecker.java:checkPermission(87)) - ACCESS CHECK: [EMAIL PROTECTED],
doCheckOwner=false, ancestorAccess=null, parentAccess=null, access=READ,
subAccess=null
[junit] 2008-02-26 12:03:36,738 INFO ipc.Server (Server.java:run(901)) -
IPC Server handler 2 on 56795, call open(/data/file1, 0, 671088640) from
127.0.0.1:56811: error: org.apache.hadoop.fs.permission.AccessControlException:
Permission denied: user=Who, access=READ,
inode="file1":hudson:supergroup:rw-------
[junit] org.apache.hadoop.fs.permission.AccessControlException: Permission
denied: user=Who, access=READ, inode="file1":hudson:supergroup:rw-------
[junit] at
org.apache.hadoop.dfs.PermissionChecker.check(PermissionChecker.java:173)
[junit] at
org.apache.hadoop.dfs.PermissionChecker.checkPermission(PermissionChecker.java:108)
[junit] at
org.apache.hadoop.dfs.FSNamesystem.checkPermission(FSNamesystem.java:4035)
[junit] at
org.apache.hadoop.dfs.FSNamesystem.checkPathAccess(FSNamesystem.java:3995)
[junit] at
org.apache.hadoop.dfs.FSNamesystem.getBlockLocations(FSNamesystem.java:755)
[junit] at
org.apache.hadoop.dfs.NameNode.getBlockLocations(NameNode.java:254)
[junit] at org.apache.hadoop.dfs.NameNode.open(NameNode.java:241)
[junit] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[junit] at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
[junit] at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
[junit] at java.lang.reflect.Method.invoke(Method.java:585)
[junit] at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:409)
[junit] at org.apache.hadoop.ipc.Server$Handler.run(Server.java:899)
[junit] 2008-02-26 12:03:36,739 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 2 on 56795,
ugi=null
[junit] 2008-02-26 12:03:36,756 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 6 on 56795,
ugi=null
[junit] 2008-02-26 12:03:36,758 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 6 on 56795,
ugi=null
[junit] Shutting down the Mini HDFS Cluster
[junit] Shutting down DataNode 2
[junit] 2008-02-26 12:03:37,727 INFO http.SocketListener
(SocketListener.java:stop(212)) - Stopped SocketListener on 0.0.0.0:56805
[junit] 2008-02-26 12:03:37,729 INFO util.Container
(Container.java:stop(156)) - Stopped [EMAIL PROTECTED]
[junit] 2008-02-26 12:03:37,888 INFO util.Container
(Container.java:stop(156)) - Stopped WebApplicationContext[/,/]
[junit] 2008-02-26 12:03:37,961 INFO util.Container
(Container.java:stop(156)) - Stopped HttpContext[/logs,/logs]
[junit] 2008-02-26 12:03:37,961 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 8 on 56795,
ugi=null
[junit] 2008-02-26 12:03:38,041 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 8 on 56795,
ugi=null
[junit] 2008-02-26 12:03:38,041 INFO util.Container
(Container.java:stop(156)) - Stopped HttpContext[/static,/static]
[junit] 2008-02-26 12:03:38,042 INFO util.Container
(Container.java:stop(156)) - Stopped [EMAIL PROTECTED]
[junit] 2008-02-26 12:03:38,043 INFO dfs.DataNode
(DataNode.java:shutdown(477)) - Waiting for threadgroup to exit, active threads
is 1
[junit] 2008-02-26 12:03:38,966 INFO dfs.DataBlockScanner
(DataBlockScanner.java:run(561)) - Exiting DataBlockScanner thread.
[junit] 2008-02-26 12:03:39,046 INFO dfs.DataNode
(DataNode.java:shutdown(477)) - Waiting for threadgroup to exit, active threads
is 0
[junit] 2008-02-26 12:03:39,047 INFO dfs.DataNode
(DataNode.java:run(2447)) - 127.0.0.1:56804:Finishing DataNode in:
FSDataset{dirpath='/zonestorage/hudson/home/hudson/hudson/jobs/Hadoop-trunk/workspace/trunk/build/test/data/dfs/data/data5/current,/zonestorage/hudson/home/hudson/hudson/jobs/Hadoop-trunk/workspace/trunk/build/test/data/dfs/data/data6/current'}
[junit] Shutting down DataNode 1
[junit] 2008-02-26 12:03:39,047 INFO util.ThreadedServer
(ThreadedServer.java:run(656)) - Stopping Acceptor
ServerSocket[addr=0.0.0.0/0.0.0.0,port=0,localport=56802]
[junit] 2008-02-26 12:03:39,048 INFO http.SocketListener
(SocketListener.java:stop(212)) - Stopped SocketListener on 0.0.0.0:56802
[junit] 2008-02-26 12:03:39,049 INFO util.Container
(Container.java:stop(156)) - Stopped [EMAIL PROTECTED]
[junit] 2008-02-26 12:03:39,117 INFO util.Container
(Container.java:stop(156)) - Stopped WebApplicationContext[/,/]
[junit] 2008-02-26 12:03:39,185 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 1 on 56795,
ugi=null
[junit] 2008-02-26 12:03:39,185 DEBUG security.UserGroupInformation
(UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 1 on 56795,
ugi=null
[junit] 2008-02-26 12:03:39,185 INFO util.Container
(Container.java:stop(156)) - Stopped HttpContext[/logs,/logs]
[junit] 2008-02-26 12:03:39,254 INFO util.Container
(Container.java:stop(156)) - Stopped HttpContext[/static,/static]
[junit] 2008-02-26 12:03:39,254 INFO util.Container
(Container.java:stop(156)) - Stopped [EMAIL PROTECTED]
[junit] 2008-02-26 12:03:39,255 INFO dfs.DataNode
(DataNode.java:shutdown(477)) - Waiting for threadgroup to exit, active threads
is 1
[junit] 2008-02-26 12:03:39,766 INFO dfs.DataNode
(DataNode.java:run(2447)) - 127.0.0.1:56801:Finishing DataNode in:
FSDataset{dirpath='/zonestorage/hudson/home/hudson/hudson/jobs/Hadoop-trunk/workspace/trunk/build/test/data/dfs/data/data3/current,/zonestorage/hudson/home/hudson/hudson/jobs/Hadoop-trunk/workspace/trunk/build/test/data/dfs/data/data4/current'}
[junit] 2008-02-26 12:03:39,906 INFO dfs.DataBlockScanner
(DataBlockScanner.java:run(561)) - Exiting DataBlockScanner thread.
[junit] 2008-02-26 12:03:40,256 INFO dfs.DataNode
(DataNode.java:shutdown(477)) - Waiting for threadgroup to exit, active threads
is 0
[junit] Shutting down DataNode 0
[junit] 2008-02-26 12:03:40,257 INFO util.ThreadedServer
(ThreadedServer.java:run(656)) - Stopping Acceptor
ServerSocket[addr=0.0.0.0/0.0.0.0,port=0,localport=56800]
[junit] 2008-02-26 12:03:40,257 INFO http.SocketListener
(SocketListener.java:stop(212)) - Stopped SocketListener on 0.0.0.0:56800
[junit] 2008-02-26 12:03:40,257 INFO util.Container
(Container.java:stop(156)) - Stopped [EMAIL PROTECTED]
[junit] 2008-02-26 12:03:40,327 INFO util.Container
(Container.java:stop(156)) - Stopped WebApplicationContext[/,/]
[junit] 2008-02-26 12:03:40,392 INFO util.Container
(Container.java:stop(156)) - Stopped HttpContext[/logs,/logs]
[junit] 2008-02-26 12:03:40,455 INFO util.Container
(Container.java:stop(156)) - Stopped HttpContext[/static,/static]
[junit] 2008-02-26 12:03:40,456 INFO util.Container
(Container.java:stop(156)) - Stopped [EMAIL PROTECTED]
[junit] 2008-02-26 12:03:40,456 INFO dfs.DataNode
(DataNode.java:shutdown(477)) - Waiting for threadgroup to exit, active threads
is 1
[junit] 2008-02-26 12:03:41,196 INFO dfs.DataBlockScanner
(DataBlockScanner.java:run(561)) - Exiting DataBlockScanner thread.
[junit] 2008-02-26 12:03:41,466 INFO dfs.DataNode
(DataNode.java:shutdown(477)) - Waiting for threadgroup to exit, active threads
is 0
[junit] 2008-02-26 12:03:41,466 INFO dfs.DataNode
(DataNode.java:run(2447)) - 127.0.0.1:56799:Finishing DataNode in:
FSDataset{dirpath='/zonestorage/hudson/home/hudson/hudson/jobs/Hadoop-trunk/workspace/trunk/build/test/data/dfs/data/data1/current,/zonestorage/hudson/home/hudson/hudson/jobs/Hadoop-trunk/workspace/trunk/build/test/data/dfs/data/data2/current'}
[junit] 2008-02-26 12:03:41,468 INFO http.SocketListener
(SocketListener.java:stop(212)) - Stopped SocketListener on 0.0.0.0:56796
[junit] 2008-02-26 12:03:41,468 INFO util.Container
(Container.java:stop(156)) - Stopped [EMAIL PROTECTED]
[junit] 2008-02-26 12:03:41,532 INFO util.Container
(Container.java:stop(156)) - Stopped WebApplicationContext[/,/]
[junit] 2008-02-26 12:03:41,595 INFO util.Container
(Container.java:stop(156)) - Stopped HttpContext[/logs,/logs]
[junit] 2008-02-26 12:03:41,655 INFO util.Container
(Container.java:stop(156)) - Stopped HttpContext[/static,/static]
[junit] 2008-02-26 12:03:41,655 INFO util.Container
(Container.java:stop(156)) - Stopped [EMAIL PROTECTED]
[junit] 2008-02-26 12:03:41,656 INFO fs.FSNamesystem
(FSEditLog.java:printStatistics(845)) - Number of transactions: 6 Total time
for transactions(ms): 1 Number of syncs: 4 SyncTimes(ms): 61 35
[junit] 2008-02-26 12:03:41,656 INFO ipc.Server (Server.java:stop(1004)) -
Stopping server on 56795
[junit] 2008-02-26 12:03:41,657 INFO ipc.Server (Server.java:run(931)) -
IPC Server handler 0 on 56795: exiting
[junit] 2008-02-26 12:03:41,657 INFO ipc.Server (Server.java:run(931)) -
IPC Server handler 7 on 56795: exiting
[junit] 2008-02-26 12:03:41,658 INFO ipc.Server (Server.java:run(931)) -
IPC Server handler 9 on 56795: exiting
[junit] 2008-02-26 12:03:41,657 INFO ipc.Server (Server.java:run(931)) -
IPC Server handler 8 on 56795: exiting
[junit] 2008-02-26 12:03:41,657 INFO ipc.Server (Server.java:run(931)) -
IPC Server handler 6 on 56795: exiting
[junit] Tests run: 2, Failures: 0, Errors: 0, Time elapsed: 19.292 sec
[junit] 2008-02-26 12:03:41,659 INFO ipc.Server (Server.java:run(495)) -
Stopping IPC Server Responder
[junit] 2008-02-26 12:03:41,657 INFO ipc.Server (Server.java:run(931)) -
IPC Server handler 5 on 56795: exiting
[junit] 2008-02-26 12:03:41,657 INFO ipc.Server (Server.java:run(931)) -
IPC Server handler 4 on 56795: exiting
[junit] 2008-02-26 12:03:41,657 INFO ipc.Server (Server.java:run(931)) -
IPC Server handler 2 on 56795: exiting
[junit] 2008-02-26 12:03:41,657 INFO ipc.Server (Server.java:run(931)) -
IPC Server handler 1 on 56795: exiting
[junit] 2008-02-26 12:03:41,657 INFO ipc.Server (Server.java:run(931)) -
IPC Server handler 3 on 56795: exiting
[junit] Running org.apache.hadoop.security.TestUnixUserGroupInformation
[junit] Tests run: 4, Failures: 0, Errors: 0, Time elapsed: 0.524 sec
[junit] Running org.apache.hadoop.util.TestReflectionUtils
[junit] Tests run: 4, Failures: 0, Errors: 0, Time elapsed: 0.682 sec
BUILD FAILED
/zonestorage/hudson/home/hudson/hudson/jobs/Hadoop-trunk/workspace/trunk/build.xml:570:
Tests failed!
Total time: 54 minutes 34 seconds
Recording fingerprints
Publishing Javadoc
Recording test results
Updating HADOOP-2345
Updating HADOOP-2873
Updating HADOOP-2655
